Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Skąd się biorą wątki i jak je obserwować?

Skąd się biorą wątki i jak je obserwować?

Kiedy po raz ostatni uruchamiałaś kod produkcyjny na jednordzeniowym procesorze? A kiedy była to prawdziwa aplikacja jednowątkowa? Od wątków które działają w naszych aplikacjach ogradzamy się warstwami abstrakcji, która obiecują zająć się wszystkimi skomplikowanymi sprawami. Niestety żeby zrozumieć jak działa aplikacja, nie sposób pominąć to z jakiego modelu wątków korzysta.

Pierwsza część prelekcji będzie powrotem do podstaw. Skąd biorą się wątki w JVM? Ile kosztuje każdy z nich? Dlaczego tworzymy pule wątków i jak z nich dobrze korzystać? I w końcu: ile wątków znajduje się w typowej aplikacji webowej i czym się zajmują?

W drugiej części zaprezentuję narzędzia do śledzenia tego, co dzieje się w aplikacji na produkcji. Myślisz, że uruchamianie profilera wątków lub pamięci na produkcji to szaleństwo? Nie, jeśli masz pod ręką odpowiednie narzędzia.

Adam Dubiel

July 12, 2019
Tweet

More Decks by Adam Dubiel

Other Decks in Programming

Transcript

  1. @dubieladam systemd(1) |-agetty(1338) |-java(1876)-+-{java}(1893) | |-{java}(1892) | |-{java}(1896) | |-{java}(1890)

    | |-{java}(1882) | |-{java}(1881) | |-{java}(1885) | |-{java}(1886) | |-{java}(1887) | |-{java}(1879) | |-{java}(1880) | |-{java}(1897) | |-{java}(1898) | |-{java}(1889)
  2. @dubieladam pthread_t tid; int ret = pthread_create(&tid, &attr, (void* (*)(void*))

    thread_native_entry, thread); http://hg.openjdk.java.net/jdk10/jdk10/hotspot/file/5ab7a67bc155/src/os/linux/vm/os_linux.cpp#l731
  3. @dubieladam Skoro wątki JVM to wątki systemowe.. widoczne z poziomu

    narzędzi systemowych schedulowane przy pomocy schedulera systemowego
  4. @dubieladam PID TID %MEM %CPU TIME COMMAND 8511 8511 28.4

    0.0 00:00:00 java 8511 8520 28.4 0.5 00:00:00 java 8511 8521 28.4 30.2 00:00:09 java 8511 8522 28.4 30.0 00:00:09 java 8511 8523 28.4 30.2 00:00:09 java 8511 8524 28.4 30.3 00:00:10 java 8511 8525 28.4 1.9 00:00:00 java 8511 8526 28.4 0.0 00:00:00 java 8511 8527 28.4 0.0 00:00:00 java 8511 8528 28.4 0.0 00:00:00 java
  5. @dubieladam PID TID %MEM %CPU TIME COMMAND 8511 8511 28.4

    0.0 00:00:00 java 8511 8520 28.4 0.5 00:00:00 java 8511 8521 28.4 30.2 00:00:09 java 8511 8522 28.4 30.0 00:00:09 java 8511 8523 28.4 30.2 00:00:09 java 8511 8524 28.4 30.3 00:00:10 java 8511 8525 28.4 1.9 00:00:00 java 8511 8526 28.4 0.0 00:00:00 java 8511 8527 28.4 0.0 00:00:00 java 8511 8528 28.4 0.0 00:00:00 java
  6. @dubieladam PID TID %MEM %CPU TIME COMMAND 8511 8511 28.4

    0.0 00:00:00 java 8511 8520 28.4 0.5 00:00:00 java 8511 8521 28.4 30.2 00:00:09 java 8511 8522 28.4 30.0 00:00:09 java 8511 8523 28.4 30.2 00:00:09 java 8511 8524 28.4 30.3 00:00:10 java 8511 8525 28.4 1.9 00:00:00 java 8511 8526 28.4 0.0 00:00:00 java 8511 8527 28.4 0.0 00:00:00 java 8511 8528 28.4 0.0 00:00:00 java
  7. @dubieladam PID TID %MEM %CPU TIME COMMAND 8511 8511 28.4

    0.0 00:00:00 java 8511 8520 28.4 0.5 00:00:00 java 8511 8521 28.4 30.2 00:00:09 java 8511 8522 28.4 30.0 00:00:09 java 8511 8523 28.4 30.2 00:00:09 java 8511 8524 28.4 30.3 00:00:10 java 8511 8525 28.4 1.9 00:00:00 java 8511 8526 28.4 0.0 00:00:00 java 8511 8527 28.4 0.0 00:00:00 java 8511 8528 28.4 0.0 00:00:00 java
  8. @dubieladam Java 8 void os::set_native_thread_name(const char *name) { // Not

    yet implemented. return; } http://hg.openjdk.java.net/jdk8/jdk8/hotspot/file/87ee5ee27509/src/os/linux/vm/os_linux.cpp#l5038
  9. @dubieladam Java 9+ void os::set_native_thread_name(const char *name) { if (Linux::_pthread_setname_np)

    { char buf [16]; // according to glibc manpage, 16 chars incl. '/0' snprintf(buf, sizeof(buf), "%s", name); buf[sizeof(buf) - 1] = '\0'; const int rc = Linux::_pthread_setname_np(pthread_self(), buf); // ERANGE should not happen; all other errors should just be ignored. assert(rc != ERANGE, "pthread_setname_np failed"); } } http://hg.openjdk.java.net/jdk10/jdk10/hotspot/file/5ab7a67bc155/src/os/linux/vm/os_linux.cpp#l5038
  10. @dubieladam Propagacja nazwy wątku Java 9+ Thread.setThreadName() propagowane do pthreads

    15 pierwszych znaków (15 + \0 = 16) nazwy wątków JVM widoczne w narzędziach systemowych
  11. @dubieladam systemd(1) |-agetty(1338) |-java(1876)-+-{C1 CompilerThre}(1893) | |-{C2 CompilerThre}(1892) | |-{Common-Cleaner}(1896)

    | |-{Finalizer}(1890) | |-{G1 Conc#0}(1882) | |-{G1 Main Marker}(1881) | |-{G1 Refine#0}(1885) | |-{G1 Refine#1}(1886) | |-{G1 Young RemSet}(1887) | |-{GC Thread#0}(1879) | |-{GC Thread#1}(1880) | |-{Service Thread}(1895) | |-{XNIO-1 Accept}(1904) | |-{XNIO-1 I/O-1}(1903)
  12. @dubieladam PID TID %MEM %CPU TIME COMMAND 3799 3799 15.9

    0.0 00:00:00 java 3799 3800 15.9 2.5 00:00:08 java 3799 3804 15.9 10.0 00:00:00 GC Thread#0 3799 3805 15.9 10.0 00:00:00 GC Thread#1 3799 3806 15.9 0.0 00:00:00 G1 Main Marker 3799 3807 15.9 0.0 00:00:00 G1 Conc#0 3799 3808 15.9 0.0 00:00:00 G1 Refine#0 3799 3809 15.9 0.0 00:00:00 G1 Refine#1 3799 3810 15.9 0.0 00:00:00 G1 Young RemSet 3799 3811 15.9 0.0 00:00:00 VM Thread
  13. @dubieladam Koszt wątku pamięć na stack - 1MB: explicit context

    switches: implicit safepointing: implicit gc roots: implicit
  14. @dubieladam Thread (reserved=18548KB, committed=18548KB) (thread #18) (stack: reserved=18468KB, committed=18468KB) (malloc=59KB

    #101) (arena=21KB #34) liczba wątków pamięć pobrana z systemu 18468KB / 18 = 1024KB
  15. @dubieladam VSZ vs RES virtual memory size przestrzeń adresowa dostępna

    dla procesu nie oznacza, że mamy tyle pamięci
  16. @dubieladam VSZ vs RES resident set size pamięć wykorzystywana przez

    proces jedyna metryka pokazująca pełne zużycie pamięci
  17. @dubieladam core file size (blocks, -c) 0 data seg size

    (kbytes, -d) unlimited scheduling priority (-e) 0 file size (blocks, -f) unlimited pending signals (-i) 7873 max locked memory (kbytes, -l) 16384 max memory size (kbytes, -m) unlimited open files (-n) 1024 pipe size (512 bytes, -p) 8 POSIX message queues (bytes, -q) 819200 real-time priority (-r) 0 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) 7873 virtual memory (kbytes, -v) unlimited file locks (-x) unlimited
  18. @dubieladam core file size (blocks, -c) 0 data seg size

    (kbytes, -d) unlimited scheduling priority (-e) 0 file size (blocks, -f) unlimited pending signals (-i) 7873 max locked memory (kbytes, -l) 16384 max memory size (kbytes, -m) unlimited open files (-n) 1024 pipe size (512 bytes, -p) 8 POSIX message queues (bytes, -q) 819200 real-time priority (-r) 0 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) 7873 virtual memory (kbytes, -v) unlimited file locks (-x) unlimited
  19. @dubieladam Koszt wątku pamięć na stack - 1MB: explicit context

    switches: implicit safepointing: implicit gc roots: implicit
  20. @dubieladam core RAM inny wątek dane w cache należą do

    poprzedniego wątku - najpewniej są bezużyteczne
  21. @dubieladam Spring default: SimpleAsyncTaskExecutor TaskExecutor implementation that fires up a

    new Thread for each task, executing it asynchronously. By default, the number of concurrent threads is unlimited. This implementation does not reuse threads!
  22. @dubieladam We should forget about small efficiencies, say about 97%

    of the time: premature optimization is the root of all evil. Yet we should not pass up our opportunities in that critical 3% Donald Knuth
  23. @dubieladam Safepoint A safepoint is a range of execution where

    the state of the executing thread is well described.
  24. @dubieladam Safepoint bias byte[] buffer = new byte[100000]; byte b

    = 0; for (int i = 0; i < size; i++) { b += buffer[i]; } // safepoint!
  25. @dubieladam Sampling profiler pl.allegro.tech.hermes.RequestFailedException: org.springframework.web.client.ResourceAccessException: I/O error on POST request

    for "": Connection refused; nested exception is java.net.ConnectException: Connection refused at pl.allegro.tech.hermes.RestTemplateHttpClient.post(RestTemplateHttpClient.java:26) at pl.allegro.tech.hermes.HermesSpanCollector.send(HermesSpanCollector.java:49) at pl.allegro.tech.hermes.HermesSpanCollector.sendSpans(HermesSpanCollector.java:43) at com.github.kristofa.brave.AbstractSpanCollector.flush(AbstractSpanCollector.java:75) at com.github.kristofa.brave.AbstractSpanCollector$Flusher.run(AbstractSpanCollector.java:95) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) org.springframework.web.client.ResourceAccessException: I/O error on POST request for "": Connection refused; nested exception is java.net.ConnectException: Connection refused at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:633) at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:595) at org.springframework.web.client.RestTemplate.postForEntity(RestTemplate.java:423) at pl.allegro.tech.hermes.RestTemplateHttpClient.post(RestTemplateHttpClient.java:22) at pl.allegro.tech.hermes.HermesSpanCollector.send(HermesSpanCollector.java:49) at pl.allegro.tech.hermes.HermesSpanCollector.sendSpans(HermesSpanCollector.java:43) at com.github.kristofa.brave.AbstractSpanCollector.flush(AbstractSpanCollector.java:75) at com.github.kristofa.brave.AbstractSpanCollector$Flusher.run(AbstractSpanCollector.java:95)
  26. @dubieladam each interval (7 ms) T1 T2 TN SIGPROF Thread

    X SIGPROF register SIGPROF handler (1x)
  27. @dubieladam Charakterystyka profilowane tylko wątki dostające czas procesora AGCT może

    nie być w stanie ustalić źródła (fail) potrzeba więcej próbek
  28. @dubieladam Środowisko pomiarowe wrk 2500 rps none (vanilla) VisualVM (JMX)

    honest-profiler async-profiler hprof warmup: 1000rps / 20s pomiar: 2500rps / 300s
  29. @dubieladam Wydajność p90+ profiler p90 [ms] p99 [ms] p999 [ms]

    vanilla 2.87 5.97 26.83 hprof 100ms 2.93 7.26 36.45 jmx 3.59 13.11 83.33 honest-profiler 2.84 6.21 33.02 async-pofiler 3.31 6.91 35.90
  30. @dubieladam Flamegraph można stworzyć z wielu formatów (w tym hprof)

    oś Y: wysokość stacku oś X: procent zajętości czasu