Preface
Sometimes we need to know the details of a program(porcess) when it is running even it`s on the edge of crach.There`s a lot of tools can be used to do these kind of job such as truss,strace,ltrace,pstack,gstack,gdb,etc.Truss and strace is focus on system call and signal generation whereas pstack,gstack,gdb are relevant with function call.Actually,pstack is a soft link of gstack,and gstack is a shell packaging script of gdb.
Introduce
pt-pmp is also relies on linux gdb.It`s a tool which aggregate gdb statck traces for a specified program especially for MySQL.pt-pmp can create and summarize full stack traces of linux process by which we can diagnose what the process is waiting for.It is mostly used in performance tuning scenarios.
Procedure
Usage
1 pt-pmp [OPTIONS] [FILES]
Parameters(few parameters in this tool)
1 --binary //Specify which binary program to trace(default `mysqld`). 2 --pid //Specify a process id to trace. 3 --iterations //Specify trace times(default "1"). 4 --interval //Number of seconds every time(default "0"). 5 --lines //Specify the number of functions to trace(default "0" means infinite). 6 --save-samples //output aggregation into a file for later analysis.
Exapmle
Trace gdb stack of mysqld into a file(start mysqld and then execute pt-pmp).
1 [root@zlm1 03:01:30 ~] 2 #pt-pmp --save-samples pmp.log 3 Sun Jul 1 03:21:06 CEST 2018 4 /usr/bin/pt-pmp: line 665: gdb: command not found //gdb package is not installed. 5 1 6 7 [root@zlm1 03:21:06 ~] 8 #yum install gdb //Install gdb package first. 9 //Omitted 10 Installed: 11 gdb.x86_64 0:7.6.1-110.el7 12 13 Complete! 14 15 [root@zlm1 03:23:19 ~] 16 #pt-pmp --save-samples pmp.log 17 Sun Jul 1 03:23:22 CEST 2018 18 10 __io_getevents_0_4(libaio.so.1),LinuxAIOHandler::collect(os0file.cc:2500),LinuxAIOHandler::poll(os0file.cc:2646),os_aio_linux_handler(os0file.cc:2702),os_aio_handler(os0file.cc:2702),fil_aio_wait(fil0fil.cc:5835),io_handler_thread(srv0start.cc:311),start_thread(libpthread.so.0),clone(libc.so.6) 19 3 pthread_cond_wait,wait(os0event.cc:165),os_event::wait_low(os0event.cc:165),srv_worker_thread(srv0srv.cc:2520),start_thread(libpthread.so.0),clone(libc.so.6) 20 1 sigwait(libpthread.so.0),signal_hand(mysqld.cc:2120),pfs_spawn_thread(pfs.cc:2190),start_thread(libpthread.so.0),clone(libc.so.6) 21 1 sigwaitinfo(libc.so.6),timer_notify_thread_func(posix_timers.c:77),pfs_spawn_thread(pfs.cc:2190),start_thread(libpthread.so.0),clone(libc.so.6) 22 1 pthread_cond_wait,wait(os0event.cc:165),os_event::wait_low(os0event.cc:165),srv_purge_coordinator_suspend(srv0srv.cc:2676),srv_purge_coordinator_thread(srv0srv.cc:2676),start_thread(libpthread.so.0),clone(libc.so.6) 23 1 pthread_cond_wait,wait(os0event.cc:165),os_event::wait_low(os0event.cc:165),buf_resize_thread(buf0buf.cc:3016),start_thread(libpthread.so.0),clone(libc.so.6) 24 1 pthread_cond_wait,wait(os0event.cc:165),os_event::wait_low(os0event.cc:165),buf_dump_thread(buf0dump.cc:782),start_thread(libpthread.so.0),clone(libc.so.6) 25 1 pthread_cond_wait,native_cond_wait(thr_cond.h:140),my_cond_wait(thr_cond.h:140),inline_mysql_cond_wait(thr_cond.h:140),compress_gtid_table(thr_cond.h:140),pfs_spawn_thread(pfs.cc:2190),start_thread(libpthread.so.0),clone(libc.so.6) 26 1 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:285),os_event::wait_time_low(os0event.cc:412),srv_monitor_thread(srv0srv.cc:1585),start_thread(libpthread.so.0),clone(libc.so.6) 27 1 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:285),os_event::wait_time_low(os0event.cc:412),srv_error_monitor_thread(srv0srv.cc:1751),start_thread(libpthread.so.0),clone(libc.so.6) 28 1 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:285),os_event::wait_time_low(os0event.cc:412),pc_sleep_if_needed(buf0flu.cc:2690),buf_flush_page_cleaner_coordinator(buf0flu.cc:2690),start_thread(libpthread.so.0),clone(libc.so.6) 29 1 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:285),os_event::wait_time_low(os0event.cc:412),lock_wait_timeout_thread(lock0wait.cc:501),start_thread(libpthread.so.0),clone(libc.so.6) 30 1 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:285),os_event::wait_time_low(os0event.cc:412),ib_wqueue_timedwait(ut0wqueue.cc:160),fts_optimize_thread(fts0opt.cc:3031),start_thread(libpthread.so.0),clone(libc.so.6) 31 1 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:285),os_event::wait_time_low(os0event.cc:412),dict_stats_thread(dict0stats_bg.cc:428),start_thread(libpthread.so.0),clone(libc.so.6) 32 1 poll(libc.so.6),vio_io_wait(viosocket.c:786),vio_socket_io_wait(viosocket.c:77),vio_read(viosocket.c:132),net_read_raw_loop(net_serv.cc:672),net_read_packet_header(net_serv.cc:756),net_read_packet(net_serv.cc:756),my_net_read(net_serv.cc:899),Protocol_classic::read_packet(protocol_classic.cc:808),Protocol_classic::get_command(protocol_classic.cc:965),do_command(sql_parse.cc:938),handle_connection(connection_handler_per_thread.cc:300),pfs_spawn_thread(pfs.cc:2190),start_thread(libpthread.so.0),clone(libc.so.6) 33 1 poll(libc.so.6),Mysqld_socket_listener::listen_for_connection_event(socket_connection.cc:852),connection_event_loop(connection_acceptor.h:66),mysqld_main(connection_acceptor.h:66),__libc_start_main(libc.so.6),_start 34 1 nanosleep(libpthread.so.0),os_thread_sleep(os0thread.cc:279),srv_master_sleep(srv0srv.cc:2330),srv_master_thread(srv0srv.cc:2330),start_thread(libpthread.so.0),clone(libc.so.6) 35 36 //Above is the messages outupted on screen.All the contents is different functions relevant with linux and mysqld. 37 //The output sorts with rules of most-frequen first. 38 //The combination of function stacks lead by "__io_getevents_0_4(libaio.so.1)"(which is relvent with io) appears 10 times.
Check the content of output file.
#more pmp.log TS 845703637.1530408066 2018-07-01 03:21:06 [New LWP 3981] [New LWP 3875] [New LWP 3874] [New LWP 3846] [New LWP 3845] [New LWP 3844] [New LWP 3843] [New LWP 3842] [New LWP 3841] [New LWP 3840] [New LWP 3839] [New LWP 3838] [New LWP 3837] [New LWP 3836] [New LWP 3835] [New LWP 3833] [New LWP 3832] [New LWP 3831] [New LWP 3830] [New LWP 3829] [New LWP 3828] [New LWP 3827] [New LWP 3826] [New LWP 3825] [New LWP 3824] [New LWP 3823] [New LWP 3822] //We got 28 new LWP from 3822 to 3981. [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib64/libthread_db.so.1". 0x00007f50efe74b7d in poll () from /lib64/libc.so.6 Thread 28 (Thread 0x7f50e7ec1700 (LWP 3822)): //It`s the last thread in pmp.log file here. #0 0x00007f50efdbf7da in sigwaitinfo () from /lib64/libc.so.6 #1 0x0000000000f5171b in timer_notify_thread_func (arg=<optimized out>) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/mysys/posix_timers.c:77 #2 0x0000000000f707b4 in pfs_spawn_thread (arg=0x30cb000) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/perfschema/pfs.cc:2190 #3 0x00007f50f13c1df5 in start_thread () from /lib64/libpthread.so.0 #4 0x00007f50efe7f1ad in clone () from /lib64/libc.so.6 Thread 27 (Thread 0x7f50ded07700 (LWP 3823)): #0 0x00007f50f11b8644 in __io_getevents_0_4 () from /lib64/libaio.so.1 #1 0x000000000106a514 in LinuxAIOHandler::collect (this=0x7f50ded06e10) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/innobase/os/os0file.cc:2500 #2 0x000000000106bc34 in LinuxAIOHandler::poll (this=0x7f50ded06e10, m1=0x7f50ded06ec8, m2=0x7f50ded06ec0, request=0x7f50ded06e90) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/innobase/os/os0file.cc:2646 #3 0x000000000106d65c in os_aio_linux_handler (request=0x7f50ded06e90, m2=0x7f50ded06ec0, m1=0x7f50ded06ec8, global_segment=0) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/innobase/os/os0file.cc:2702 #4 os_aio_handler (segment=0, m1=0x7f50ded06ec8, m2=0x7f50ded06ec0, request=0x7f50ded06e90) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/innobase/os/os0file.cc:6259 #5 0x000000000120196d in fil_aio_wait (segment=0) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/innobase/fil/fil0fil.cc:5835 #6 0x000000000110e980 in io_handler_thread (arg=<optimized out>) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/innobase/srv/srv0start.cc:311 #7 0x00007f50f13c1df5 in start_thread () from /lib64/libpthread.so.0 #8 0x00007f50efe7f1ad in clone () from /lib64/libc.so.6 Thread 26 (Thread 0x7f50de506700 (LWP 3824)): #0 0x00007f50f11b8644 in __io_getevents_0_4 () from /lib64/libaio.so.1 #1 0x000000000106a514 in LinuxAIOHandler::collect (this=0x7f50de505e10) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/innobase/os/os0file.cc:2500 #2 0x000000000106bc34 in LinuxAIOHandler::poll (this=0x7f50de505e10, m1=0x7f50de505ec8, m2=0x7f50de505ec0, request=0x7f50de505e90) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/innobase/os/os0file.cc:2646 #3 0x000000000106d65c in os_aio_linux_handler (request=0x7f50de505e90, m2=0x7f50de505ec0, m1=0x7f50de505ec8, global_segment=1) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/innobase/os/os0file.cc:2702 #4 os_aio_handler (segment=1, m1=0x7f50de505ec8, m2=0x7f50de505ec0, request=0x7f50de505e90) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/innobase/os/os0file.cc:6259 #5 0x000000000120196d in fil_aio_wait (segment=1) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/innobase/fil/fil0fil.cc:5835 #6 0x000000000110e980 in io_handler_thread (arg=<optimized out>) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/innobase/srv/srv0start.cc:311 #7 0x00007f50f13c1df5 in start_thread () from /lib64/libpthread.so.0 #8 0x00007f50efe7f1ad in clone () from /lib64/libc.so.6 //Omitted. Thread 4 (Thread 0x7f50deeb2700 (LWP 3874)): #0 0x00007f50f13c8ec1 in sigwait () from /lib64/libpthread.so.0 #1 0x00000000007c357b in signal_hand (arg=<optimized out>) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/mysqld.cc:2120 #2 0x0000000000f707b4 in pfs_spawn_thread (arg=0x386a740) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/perfschema/pfs.cc:2190 #3 0x00007f50f13c1df5 in start_thread () from /lib64/libpthread.so.0 #4 0x00007f50efe7f1ad in clone () from /lib64/libc.so.6 Thread 3 (Thread 0x7f50be7fc700 (LWP 3875)): #0 0x00007f50f13c5705 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000ebe6f5 in native_cond_wait (mutex=<optimized out>, cond=<optimized out>) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/include/thr_cond.h:140 #2 my_cond_wait (mp=<optimized out>, cond=<optimized out>) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/include/thr_cond.h:195 #3 inline_mysql_cond_wait (src_line=874, src_file=0x15d92e0 "/export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/rpl_gtid_persist.cc", mutex=<optimized out>, that=<optimized out>) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/include/mysql/psi/mysql_thread.h:1184 #4 compress_gtid_table (p_thd=<optimized out>) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/rpl_gtid_persist.cc:874 #5 0x0000000000f707b4 in pfs_spawn_thread (arg=0x386a740) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/perfschema/pfs.cc:2190 #6 0x00007f50f13c1df5 in start_thread () from /lib64/libpthread.so.0 #7 0x00007f50efe7f1ad in clone () from /lib64/libc.so.6 Thread 2 (Thread 0x7f50dee81700 (LWP 3981)): #0 0x00007f50efe74b7d in poll () from /lib64/libc.so.6 #1 0x00000000012bae8f in vio_io_wait (vio=<optimized out>, event=<optimized out>, timeout=300000) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/vio/viosocket.c:786 #2 0x00000000012baf83 in vio_socket_io_wait (vio=<optimized out>, event=<optimized out>) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/vio/viosocket.c:77 #3 0x00000000012bb5b8 in vio_read (vio=0x7f50b0000bb0, buf=0x7f50b000a3c0 "