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.

Transcript

1. @dubieladam Adam Dubiel Skąd się biorą wątki i jak je obserwować?
2. @dubieladam github.com/adamdubiel @dubieladam
3. @dubieladam
4. @dubieladam
5. @dubieladam
6. @dubieladam
7. @dubieladam startuje JVM
8. @dubieladam pojawiają się wątki maszyny wirtualnej (~20 wątków)
9. @dubieladam wstaje spring context (+~15 wątków)
10. @dubieladam zaczyna się ruch (+~80 wątków)
11. @dubieladam Narodziny procesu
12. @dubieladam systemd(1) |-agetty(1338) |-sshd(1133)---sshd(1790)---bash(1791)
13. @dubieladam java -version
14. @dubieladam systemd(1) |-agetty(1338) |-sshd(1133)-...-bash(1791)-java(1876)
15. @dubieladam systemd(1) |-agetty(1338) |-java(1876)
16. @dubieladam Proces Pamięć T1 T2 TN
17. @dubieladam Wątki w JVM
18. @dubieladam pstree -Ap
19. @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)
20. @dubieladam Wątek JVM == wątek systemowy
21. @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
22. @dubieladam Skoro wątki JVM to wątki systemowe.. widoczne z poziomu narzędzi systemowych schedulowane przy pomocy schedulera systemowego
23. @dubieladam ls /proc/1876/task 1876 1893 1892 1896 1890 1882 1881 1885 1886 1887 1879 1880 1897 1898 1889
24. @dubieladam ps H -p <pid> -o pid,tid,pmem,pcpu,time,comm
25. @dubieladam top -H -p <pid>
26. @dubieladam ps H -p <pid> -o pid,tid,pmem,pcpu,time,comm process id thread id
27. @dubieladam
28. @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
29. @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
30. @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
31. @dubieladam Jak połączyć wątek systemowy z wątkiem JVM?
32. @dubieladam jstack <pid>
33. @dubieladam jcmd <pid> Thread.print
34. @dubieladam "pool-1-thread-10" #19 prio=5 os_prio=31 tid=0x00007fcd05868000 nid=0x6103 runnable [0x000070000ffc5000]
35. @dubieladam "pool-1-thread-10" #19 prio=5 os_prio=31 tid=0x00007fcd05868000 nid=0x6103 runnable [0x000070000ffc5000]
36. @dubieladam pool-1-thread-10 tid=0x00007fcd05868000 nid=0x6103 hex(pthreads id) hex(tid)
37. @dubieladam pool-1-thread-10 nid=0x6103
38. @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
39. @dubieladam hex(8521) = 2149 jstack <pid> | grep -i 2149
40. @dubieladam jstack <pid> | grep `printf %x 8521`
41. @dubieladam "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fd7ec01f800 nid=0x2149 runnable hex(8521)
42. @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
43. @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
44. @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
45. @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)
46. @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
47. @dubieladam
48. @dubieladam Ile kosztuje wątek?
49. @dubieladam Koszt wątku pamięć na stack - 1MB: explicit context switches: implicit safepointing: implicit gc roots: implicit
50. @dubieladam Stos wątku
51. @dubieladam Heap Offheap tutaj żyją stacki wątków
52. @dubieladam java -XX:+UnlockDiagnosticVMOptions -XX:NativeMemoryTracking=summary -XX:+PrintNMTStatistics -version
53. @dubieladam java -XX:+UnlockDiagnosticVMOptions -XX:NativeMemoryTracking=summary -XX:+PrintNMTStatistics -version
54. @dubieladam Thread (reserved=18548KB, committed=18548KB) (thread #18) (stack: reserved=18468KB, committed=18468KB) (malloc=59KB #101) (arena=21KB #34)
55. @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
56. @dubieladam total app memory = heap size + thread count * stack size + ...
57. @dubieladam Ile wątków mogę stworzyć? Heap Offheap RAM
58. @dubieladam Ile wątków mogę stworzyć? Heap Offheap RAM 2GB 500MB
59. @dubieladam Ile wątków mogę stworzyć? Heap Offheap RAM 2GB 512MB 300MB na rzeczy.. 1.2GB fna wątki
60. @dubieladam Ile wątków mogę stworzyć? 1.2GB / 1MB = 1200
61. @dubieladam
62. @dubieladam
63. @dubieladam VSZ vs RES
64. @dubieladam VSZ vs RES virtual memory size przestrzeń adresowa dostępna dla procesu nie oznacza, że mamy tyle pamięci
65. @dubieladam VSZ vs RES resident set size pamięć wykorzystywana przez proces jedyna metryka pokazująca pełne zużycie pamięci
66. @dubieladam
67. @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
68. @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
69. @dubieladam Mniej to więcej?
70. @dubieladam CPU CPU CPU CPU waiting..
71. @dubieladam Koszt wątku pamięć na stack - 1MB: explicit context switches: implicit safepointing: implicit gc roots: implicit
72. @dubieladam Context switch
73. @dubieladam core L3 cache L1 cache L2 cache wspólne ekskluzywny
74. @dubieladam core L3 cache L1 cache L2 cache <1 ns ~4 ns ~20-40 ns ~100 ns RAM
75. @dubieladam core RAM przepływ danych L2 -> L1
76. @dubieladam core RAM inny wątek dane w cache należą do poprzedniego wątku - najpewniej są bezużyteczne
77. @dubieladam Context switches mogą trwać nawet 30 mikrosekund do zaobserwowania przez perf i vmstat
78. @dubieladam CPU CPU CPU CPU
79. @dubieladam Wracając do aplikacji...
80. @dubieladam
81. @dubieladam pojawiają się wątki maszyny wirtualnej (~20 wątków)
82. @dubieladam G1 GC threads VMThread C1 & C2 PeriodicTaskThread
83. @dubieladam zaczyna się ruch (+~80 wątków) wstaje spring context (+~15 wątków)
84. @dubieladam Zarządzanie wątkami
85. @dubieladam new Thread() Executors.fixedThreadPool()
86. @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!
87. @dubieladam Thread pool
88. @dubieladam Thread pool co się stanie, kiedy jest pełna?
89. @dubieladam Thread pool jaki rozmiar ma kolejka?
90. @dubieladam Thread pool
91. @dubieladam new ThreadPoolExecutor( corePoolSize, maxPoolSize, keepAliveTime, keepAliveTimeUnit, taskQueue, threadFactory, rejectionPolicy )
92. @dubieladam new ThreadPoolExecutor( corePoolSize, maxPoolSize, keepAliveTime, keepAliveTimeUnit, taskQueue, threadFactory, rejectionPolicy ) implementacja kolejki
93. @dubieladam new ThreadPoolExecutor( corePoolSize, maxPoolSize, keepAliveTime, keepAliveTimeUnit, taskQueue, threadFactory, rejectionPolicy ) co się dzieje, kiedy kolejka jest pełna
94. @dubieladam Rejection: Happy path Thread Pool Caller Thread
95. @dubieladam Rejection: Default unhappy path Thread Pool Caller Thread
96. @dubieladam Rejection: CallerRunsPolicy Thread Pool Caller Thread
97. @dubieladam Rejection: AbortPolicy Thread Pool Caller Thread Rejected Execution Exception
98. @dubieladam ThreadPoolExecutor.DiscardPolicy Thread Pool Caller Thread /dev/null
99. @dubieladam ThreadPoolExecutor.DiscardOldestPolicy Thread Pool Caller Thread /dev/null
100. @dubieladam zaczyna się ruch (+~80 wątków)
101. @dubieladam
102. @dubieladam
103. @dubieladam raz użyte, pozostają w puli do reużycia
104. @dubieladam ThreadPoolExecutor.prestartAllCoreThreads()
105. @dubieladam zaczyna się ruch (+~80 wątków) spring context boots up (+~15 threads)
106. @dubieladam -Xlog:thread+os:file=/tmp/threads.log
107. @dubieladam Jak obserwować wątki?
108. @dubieladam
109. @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
110. @dubieladam Profilery sampling instrumenting
111. @dubieladam Profilery kłamiące prawie uczciwe uczciwe
112. @dubieladam
113. @dubieladam T1 T2 TN T1 T2 TN safepoint JvmtiEnv::GetAllStackTraces each sampling_interval (100 ms)
114. @dubieladam Safepoint A safepoint is a range of execution where the state of the executing thread is well described.
115. @dubieladam Safepoint interpreted • każda instrukcja compiled • wyjście z metody • po iteracji uncounted loop
116. @dubieladam Safepoint C1 C2 safepoint! zbierz dane
117. @dubieladam Safepoint bias byte[] buffer = new byte[100000]; byte b = 0; for (int i = 0; i < size; i++) { b += buffer[i]; } // safepoint!
118. @dubieladam Sampling profiler T1 T2 TN O(n)
119. @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)
120. @dubieladam AsyncGetCallTrace
121. @dubieladam each interval (7 ms) T1 T2 TN SIGPROF Thread X SIGPROF register SIGPROF handler (1x)
122. @dubieladam each interval (7 ms) Thread X SIGPROF handler AsyncGetCallTrace jmethodId BCI MPSC z prealokowaną pamięcią
123. @dubieladam .hpl Postprocessing (async)
124. @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
125. @dubieladam Przedstawiciele Java Mission Control honest-profiler async-profiler*
126. @dubieladam Jakie to ma znaczenie?
127. @dubieladam Środowisko pomiarowe wrk 2500 rps none (vanilla) VisualVM (JMX) honest-profiler async-profiler hprof warmup: 1000rps / 20s pomiar: 2500rps / 300s
128. @dubieladam Pomiary time to safepoint / stop time aktywność GC
129. @dubieladam
130. @dubieladam
131. @dubieladam Wydajność? pomiary za pomocą wrk2 brak efektu coordinated omission pomiar szczegółowy percentyli
132. @dubieladam
133. @dubieladam
134. @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
135. @dubieladam Wyniki
136. @dubieladam
137. @dubieladam Flamegraphs!
138. @dubieladam
139. @dubieladam Flamegraph można stworzyć z wielu formatów (w tym hprof) oś Y: wysokość stacku oś X: procent zajętości czasu
140. @dubieladam Po co tyle profilerów?
141. @dubieladam honest-profiler tylko AGCT … więc widzi tylko kod JVM w pozostałych przypadkach - unknown
142. @dubieladam
143. @dubieladam async-profiler AGCT + perf_events JVM + system operacyjny
144. @dubieladam
145. @dubieladam I HEARD YOU LIKE PROFILERS SO I PUT PROFILER ON A PROFILER
146. @dubieladam
147. @dubieladam github.com/adamdubiel @dubieladam