Something isn't right here

Transcript

1. something isn’t right here
2. meet our pet python service 80 requests /second /backend 200,000 lines 79 libraries python 2.7 gunicorn tornado
3. system and user total cpu usage (2 cores) System User
5. $ df -h pre-flight checklist Filesystem Size Used Avail Use% Mounted on /dev/mapper/vg-root 18G 4,6G 13G 28% / $ df -i Filesystem Inodes IUsed IFree IUse% Mounted on /dev/mapper/vg-root 1155440 158744 996696 14% /
6. $ ss -s pre-flight checklist Total: 1471 (kernel 1908) TCP: 5215 (estab 643, closed 4562, orphaned 0, synrecv 0, timewait 4560/0) Transport Total IP IPv6 * 1908 - - RAW 0 0 0 UDP 262 258 4 TCP 653 651 2 INET 915 909 6 FRAG 0 0 0
7. $ vmstat -Sm 1 pre-flight checklist vmstat 1 -Sm procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 0 0 68 350 175 1154 0 0 0 21 2 1 3 2 96 0 1 0 68 346 175 1154 0 0 0 0 401 730 2 5 93 0 1 0 68 349 175 1154 0 0 0 0 958 1631 30 21 49 0 1 0 68 347 175 1154 0 0 0 0 1822 4428 18 35 46 0 0 0 68 342 175 1154 0 0 0 72 967 1917 27 25 49 0
9. $ top “Each process using or waiting for CPU (the ready queue or run queue) increments the load number by 1” - said someone on Wikipedia
10. $ lscpu Architecture: x86_64 CPU op-mode(s): 32-bit, 64-bit Byte Order: Little Endian CPU(s): 2 ... $ top
11. $ top
12. $ top
13. $ top
14. $ top
15. $ top
16. $ top
17. PPID PID WCHAN THCNT STAT CMD 1 17383 poll_s 1 Ss /usr/bin/python /usr... (supervisor) 17383 11145 poll_s 1 S \_ /usr/local/tal... (gunicorn) 11145 11150 - 49 Rl \_ /usr/local/tal... (service) 11145 11155 - 47 Rl \_ /usr/local/tal... (service) 11145 11160 - 45 Rl \_ /usr/local/tal... (service) 11145 11170 - 47 Rl \_ /usr/local/tal... (service) 11145 11172 - 49 Rl \_ /usr/local/tal... (service) 11145 11180 - 49 Rl \_ /usr/local/tal... (service) 11145 11185 - 47 Rl \_ /usr/local/tal... (service) 11145 11186 - 47 Rl \_ /usr/local/tal... (service) ... address of the kernel function where the process is sleeping (use wchan if you want the kernel function name). Running tasks will display a dash ('-') in this column. WCHAN $ ps axfoppid,pid,wchan,thcount,stat,cmd
18. PPID PID WCHAN THCNT STAT CMD 1 17383 poll_s 1 Ss /usr/bin/python /usr... (supervisor) 17383 11145 poll_s 1 S \_ /usr/local/tal... (gunicorn) 11145 11150 - 49 Rl \_ /usr/local/tal... (service) 11145 11155 - 47 Rl \_ /usr/local/tal... (service) 11145 11160 - 45 Rl \_ /usr/local/tal... (service) 11145 11170 - 47 Rl \_ /usr/local/tal... (service) 11145 11172 - 49 Rl \_ /usr/local/tal... (service) 11145 11180 - 49 Rl \_ /usr/local/tal... (service) 11145 11185 - 47 Rl \_ /usr/local/tal... (service) 11145 11186 - 47 Rl \_ /usr/local/tal... (service) ... 45 threads per process, something doesn’t feel right $ ps axfoppid,pid,wchan,thcount,stat,cmd
19. So we add some logging in python
20. pykafka So we add some logging in python
21. 14:59:10 TGID TID cswch/s nvcswch/s Command 14:59:11 14528 - 19,00 0,00 supervisord 14:59:11 - 14528 19,00 0,00 |__supervisord 14:59:11 16671 - 1,00 0,00 gunicorn 14:59:11 - 16671 1,00 0,00 |__gunicorn 14:59:11 16676 - 62,00 181,00 gunicorn 14:59:11 - 16676 62,00 182,00 |__gunicorn 14:59:11 - 16700 32,00 0,00 |__gunicorn 14:59:11 - 16701 36,00 0,00 |__gunicorn 14:59:11 - 16702 48,00 0,00 |__gunicorn 14:59:11 - 16703 57,00 1,00 |__gunicorn 14:59:11 - 16704 63,00 0,00 |__gunicorn 14:59:11 - 16706 62,00 0,00 |__gunicorn 14:59:11 - 16707 53,00 0,00 |__gunicorn 14:59:11 - 16708 24,00 0,00 |__gunicorn 14:59:11 - 16709 52,00 0,00 |__gunicorn 14:59:11 - 16711 118,00 0,00 |__gunicorn 14:59:11 - 16712 25,00 0,00 |__gunicorn 14:59:11 - 16713 99,00 1,00 |__gunicorn 14:59:11 - 16720 143,00 1,00 |__gunicorn 14:59:11 - 16722 24,00 0,00 |__gunicorn 14:59:11 - 16723 28,00 1,00 |__gunicorn $ pidstat -t -w -p 14528 1
22. 30 -150 context switches 40 workers ±100,000 context switches per second 45 threads approximately each task using an average of 0.01ms cpu time every second
23. system usage explained context switching takes resources but why is it doing so many voluntary context switches?
24. % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- -------------- 89.73 8.212806 5039 1630 select 10.09 0.923402 290 3184 357 futex 0.15 0.013721 8 1733 gettimeofday 0.03 0.002397 799 3 poll 0.01 0.000540 14 39 fchmod $ strace -c -f -p 14528 select - “allow a program to monitor multiple file descriptors, waiting until one or more of the file descriptors become "ready" for some class of IO operation” futex - “this system call is typically used to implement the contended case of a lock in shared memory”
25. 1 (gdb) info threads 2 Id Target Id Frame 3 36 Thread 0x7fd9aa31d700 (LWP 2320) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 4 35 Thread 0x7fd9a9a1b700 (LWP 2321) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 5 34 Thread 0x7fd9a9119700 (LWP 2322) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 6 33 Thread 0x7fd9a8817700 (LWP 2323) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 7 32 Thread 0x7fd993efe700 (LWP 2324) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 8 31 Thread 0x7fd992dfb700 (LWP 2326) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 9 30 Thread 0x7fd9925fa700 (LWP 2327) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 10 29 Thread 0x7fd991df9700 (LWP 2328) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 11 28 Thread 0x7fd9915f8700 (LWP 2329) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 12 27 Thread 0x7fd973fff700 (LWP 2331) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 13 26 Thread 0x7fd9737fe700 (LWP 2332) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 14 25 Thread 0x7fd972ffd700 (LWP 2333) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 15 24 Thread 0x7fd971ffb700 (LWP 2335) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 16 23 Thread 0x7fd9717fa700 (LWP 2336) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 17 22 Thread 0x7fd970ff9700 (LWP 2337) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 18 21 Thread 0x7fd963fff700 (LWP 2338) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 19 20 Thread 0x7fd962ffd700 (LWP 2340) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 20 19 Thread 0x7fd9637fe700 (LWP 2350) "gunicorn" 0x00007fd9b71919b3 in epoll_wait () from /lib/x86_64-linux-gnu/libc.so.6 21 18 Thread 0x7fd9727fc700 (LWP 2351) "gunicorn" 0x00007fd9b71919b3 in epoll_wait () from /lib/x86_64-linux-gnu/libc.so.6 22 17 Thread 0x7fd95dff3700 (LWP 2778) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 23 16 Thread 0x7fd95cff1700 (LWP 2780) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 24 15 Thread 0x7fd95bfef700 (LWP 2781) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 25 14 Thread 0x7fd95d7f2700 (LWP 2782) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 26 13 Thread 0x7fd9ab144700 (LWP 2783) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 27 12 Thread 0x7fd990df7700 (LWP 2784) "gunicorn" 0x00007fd9b71919b3 in epoll_wait () from /lib/x86_64-linux-gnu/libc.so.6 28 11 Thread 0x7fd9627fc700 (LWP 2785) "gunicorn" 0x00007fd9b71919b3 in epoll_wait () from /lib/x86_64-linux-gnu/libc.so.6 29 10 Thread 0x7fd961ffb700 (LWP 2786) "gunicorn" 0x00007fd9b71919b3 in epoll_wait () from /lib/x86_64-linux-gnu/libc.so.6 30 9 Thread 0x7fd9617fa700 (LWP 2787) "gunicorn" 0x00007fd9b71919b3 in epoll_wait () from /lib/x86_64-linux-gnu/libc.so.6 31 8 Thread 0x7fd960ff9700 (LWP 2951) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 32 7 Thread 0x7fd95fff7700 (LWP 3291) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 33 6 Thread 0x7fd95f7f6700 (LWP 3292) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 34 5 Thread 0x7fd95eff5700 (LWP 3293) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 35 4 Thread 0x7fd95e7f4700 (LWP 3294) "gunicorn" 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 36 3 Thread 0x7fd9607f8700 (LWP 5609) "gunicorn" 0x00007fd9b71919b3 in epoll_wait () from /lib/x86_64-linux-gnu/libc.so.6 37 2 Thread 0x7fd95c7f0700 (LWP 5610) "gunicorn" 0x00007fd9b71919b3 in epoll_wait () from /lib/x86_64-linux-gnu/libc.so.6 38 * 1 Thread 0x7fd9b7f93700 (LWP 2286) "gunicorn" 0x00000000004496ed in lookdict_string (mp=<optimized out>, key=0x7fd9b7e84810, hash=8176488447408857113) at Objects/dictobject.c:430 $ gdb -p 14528 (gdb) info threads
26. 2 #0 0x00007fd9b7b6cfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 3 #1 0x00000000004d3258 in PyThread_acquire_lock (lock=0x1cfcc10, waitflag=<optimized out>) at Python/thread_pthread.h:321 4 #2 0x0000000000496c64 in PyEval_RestoreThread (tstate=0x37b7e80) at Python/ceval.c:357 5 #3 0x00007fd9b51d8038 in floatsleep (secs=<optimized out>) at /usr/local/src/Python-2.7.3/Modules/timemodule.c:954 6 #4 time_sleep (self=<optimized out>, args=<optimized out>) at /usr/local/src/Python-2.7.3/Modules/timemodule.c:206 7 #5 0x000000000049cacd in call_function (oparg=<optimized out>, pp_stack=0x7fd9aa31c110) at Python/ceval.c:4021 8 #6 PyEval_EvalFrameEx (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:2666 9 #7 0x000000000049e676 in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=<optimized out>, args=<optimized out>, argcount=2, kws=0x4beb kwcount=0, defs=0x1b8d528, defcount=1, closure=0x0) at Python/ceval.c:3253 10 #8 0x000000000049c555 in fast_function (nk=<optimized out>, na=2, n=<optimized out>, pp_stack=0x7fd9aa31c300, func=0x1c1a2a8) at Python/ceval.c:4117 11 #9 call_function (oparg=<optimized out>, pp_stack=0x7fd9aa31c300) at Python/ceval.c:4042 12 #10 PyEval_EvalFrameEx (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:2666 13 #11 0x000000000049e676 in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=<optimized out>, args=<optimized out>, argcount=1, kws=0x7fd99c001090, kwcount=1, defs=0x1def968, defcount=2, closure=0x0) at Python/ceval.c:3253 14 #12 0x000000000049c555 in fast_function (nk=<optimized out>, na=1, n=<optimized out>, pp_stack=0x7fd9aa31c4f0, func=0x1e269b0) at Python/ceval.c:4117 15 #13 call_function (oparg=<optimized out>, pp_stack=0x7fd9aa31c4f0) at Python/ceval.c:4042 16 #14 PyEval_EvalFrameEx (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:2666 17 #15 0x000000000049e676 in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=<optimized out>, args=<optimized out>, argcount=0, kws=0x7fd9b7f52068, kwcount=0, defs=0x0, defcount=0, closure=0x48b1e90) at Python/ceval.c:3253 18 #16 0x00000000004fff23 in function_call (func=0x48b76e0, arg=0x7fd9b7f52050, kw=0x4956e70) at Objects/funcobject.c:526 19 #17 0x000000000041eda7 in PyObject_Call (func=0x48b76e0, arg=<optimized out>, kw=<optimized out>) at Objects/abstract.c:2529 20 #18 0x0000000000499464 in ext_do_call (nk=0, na=<optimized out>, flags=<optimized out>, pp_stack=0x7fd9aa31c7a0, func=0x48b76e0) at Python/ceval.c:4334 21 #19 PyEval_EvalFrameEx (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:2705 22 #20 0x000000000049d762 in fast_function (nk=<optimized out>, na=1, n=<optimized out>, pp_stack=0x7fd9aa31c8e0, func=0x1c1ae60) at Python/ceval.c:4107 23 #21 call_function (oparg=<optimized out>, pp_stack=0x7fd9aa31c8e0) at Python/ceval.c:4042 24 #22 PyEval_EvalFrameEx (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:2666 25 #23 0x000000000049d762 in fast_function (nk=<optimized out>, na=1, n=<optimized out>, pp_stack=0x7fd9aa31ca20, func=0x1c1b050) at Python/ceval.c:4107 26 #24 call_function (oparg=<optimized out>, pp_stack=0x7fd9aa31ca20) at Python/ceval.c:4042 27 #25 PyEval_EvalFrameEx (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:2666 28 #26 0x000000000049e676 in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=<optimized out>, args=<optimized out>, argcount=1, kws=0x0, kwcount=0, defs=0x0, defcount=0, closure=0x0) at Python/ceval.c:3253 29 #27 0x00000000004ffe2c in function_call (func=0x1c1aed8, arg=0x48b1ed0, kw=0x0) at Objects/funcobject.c:526 30 #28 0x000000000041eda7 in PyObject_Call (func=0x1c1aed8, arg=<optimized out>, kw=<optimized out>) at Objects/abstract.c:2529 31 #29 0x00000000004224cf in instancemethod_call (func=0x1c1aed8, arg=0x48b1ed0, kw=0x0) at Objects/classobject.c:2578 32 #30 0x000000000041eda7 in PyObject_Call (func=0x48b3b40, arg=<optimized out>, kw=<optimized out>) at Objects/abstract.c:2529 33 #31 0x00000000004972c7 in PyEval_CallObjectWithKeywords (func=0x48b3b40, arg=0x7fd9b7f52050, kw=<optimized out>) at Python/ceval.c:3890 34 #32 0x00000000004d6712 in t_bootstrap (boot_raw=<optimized out>) at ./Modules/threadmodule.c:614 35 #33 0x00007fd9b7b66e9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 36 #34 0x00007fd9b719131d in clone () from /lib/x86_64-linux-gnu/libc.so.6 37 #35 0x0000000000000000 in ?? () (gdb) bt
27. python.org
28. the infamous Python2 GIL Python 2.7* https://wiki.python.org/moin/GlobalInterpreterLock
29. time 1 thread in a Python2 process has the Global Interpreter Lock at any one time t1 t2 t3 t4 P1
30. Python threads are scheduled like all other threads
31. What if 100 ticks is not enough involuntary switch voluntary switch
32. contention http://www.cs.montana.edu/~chandrima.sarkar/AdvancedOS/CSCI560_Proj_main/index.html With 45 threads, we’re contending for the GIL as the Python level With 40 worker processes, we’re contending with other processes as the OS level
33. linux scheduler is more complex http://www.cs.montana.edu/~chandrima.sarkar/AdvancedOS/CSCI560_Proj_main/index.html red-black tree, multi-cpu, numa, priorities, cgroups, etc
34. ±100,000 voluntary context switches (GIL acquire attempts) our reality ±50 involuntary context switches (forced off CPU) Wasted Effort
36. we made some changes 4 workers Less CPU contention, More efficiency Use average response time to work out concurrency constraints.
37. we made some changes rdkafka Just 2 threads in total Reduced number of threads that never do any work.
38. perf_events > perf record -F 99 -p PID > perf report
39. flamegraphs Global Interpreter Lock Python OpCode Interpreter Application Stuff
40. www.takealot.com/careers we’re hiring