Percona-Tookit工具包之pt-pmp

 

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

pt-pmp [OPTIONS] [FILES]

 

Parameters(few parameters in this tool)

--binary //Specify which binary program to trace(default 'mysqld').
--pid //Specify a process id to trace.
--iterations //Specify trace times(default "1").
--interval //Number of seconds every time(default "0"). 
--lines //Specify the number of functions to trace(default "0" means infinite).
--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).

[root@zlm1 03:01:30 ~]
#pt-pmp --save-samples pmp.log
Sun Jul  1 03:21:06 CEST 2018
/usr/bin/pt-pmp: line 665: gdb: command not found //gdb package is not installed.
      1 

[root@zlm1 03:21:06 ~]
#yum install gdb //Install gdb package first.
//Omitted
Installed:
  gdb.x86_64 0:7.6.1-110.el7                                                                                                                         

Complete!

[root@zlm1 03:23:19 ~]
#pt-pmp --save-samples pmp.log
Sun Jul  1 03:23:22 CEST 2018
     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)
      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)
      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)
      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)
      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)
      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)
      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)
      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)
      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)
      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)
      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)
      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)
      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)
      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)
      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)
      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
      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)
      
//Above is the messages outupted on screen.All the contents is different functions relevant with linux and mysqld.
//The output sorts with rules of most-frequen first.
//The combination of function stacks lead by "__io_getevents_0_4(libaio.so.1)"(which is relevant 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 "\001", size=4) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/vio/viosocket.c:132
#4  0x0000000000c6de03 in net_read_raw_loop (net=0x7f50b0002570, count=4) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/net_serv.cc:672
#5  0x0000000000c6e69b in net_read_packet_header (net=0x7f50b0002570) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/net_serv.cc:756
#6  net_read_packet (net=0x7f50b0002570, complen=0x7f50dee80d38) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/net_serv.cc:822
#7  0x0000000000c6e94c in my_net_read (net=0x7f50b0002570) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/net_serv.cc:899
#8  0x0000000000c7c1dc in Protocol_classic::read_packet (this=0x7f50b0001e18) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/protocol_classic.cc:808
#9  0x0000000000c7af52 in Protocol_classic::get_command (this=0x7f50b0001e18, com_data=0x7f50dee80de0, cmd=0x7f50dee80e0c) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/protocol_classic.cc:965
#10 0x0000000000d1cf47 in do_command (thd=0x7f50b0000dc0) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/sql_parse.cc:938
#11 0x0000000000ded7ac in handle_connection (arg=<optimized out>) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/conn_handler/connection_handler_per_thread.cc:300
#12 0x0000000000f707b4 in pfs_spawn_thread (arg=0x382fa60) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/storage/perfschema/pfs.cc:2190
#13 0x00007f50f13c1df5 in start_thread () from /lib64/libpthread.so.0
#14 0x00007f50efe7f1ad in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x7f50f17e8740 (LWP 3817)):
#0  0x00007f50efe74b7d in poll () from /lib64/libc.so.6
#1  0x0000000000deeaf9 in Mysqld_socket_listener::listen_for_connection_event (this=0x30d96f0) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/conn_handler/socket_connection.cc:852
#2  0x00000000007c89c4 in connection_event_loop (this=0x373e050) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/conn_handler/connection_acceptor.h:66
#3  mysqld_main (argc=79, argv=0x2f897b8) at /export/home/pb2/build/sb_0-26514852-1514433850.9/mysql-5.7.21/sql/mysqld.cc:5122
#4  0x00007f50efdaaaf5 in __libc_start_main () from /lib64/libc.so.6
#5  0x00000000007be479 in _start ()
TS 788084395.1530408210 2018-07-01 03:23:30

[root@zlm1 03:37:50 ~]
#

 

Demonstrate of relevant conceptions.

1.What's gdb?
gdb is tool of linux,a debugger of GNU project.It can help you to see what's going on inside the program while it executes.For example,the usual case is the program running slowly or almost to be crashed.

2.What can gdb do?
It can catch details in the act belowl:
1).Start the program and specify anything the might affect its behavior.
2).Let the program stop on specific conditions.
3).Check the details when the program stops.
4).Change things in the program and try to correct effect of potential problems.

3.What's LWP?
LWP is abbreviation of Light Weight Process.
Process:You'll find a process in background after you've executed a linux command(which can be observed by "ps -ef").
Thread:It's nothing but a flow of execution of the linux process.
Light Weight Process:It's almost the same with "thread" but a term at kernal level.

Here's some detail of it:
What are Linux Processes, Threads, Light Weight Processes, and Process State
https://www.thegeekstuff.com/2013/11/linux-process-and-threads/ 

 

Something about output file.

1.The second column in the file shows the detail of memory address with hex.
2.At the very beginning of the file in Thread 1(LWP 3817),it shows the detail of how MySQL process works.
"Mysqld_socket_listener::listen_for_connection_event" is a MySQL function defined in source code file "socket_connection.cc".This is a clue which can help you to findout where to servay the details if something happened and stucked here.
3.At every bottom of each thread(except thread 1),you can see the same contents below:
"#. 0x... clone () from /lib64/libc.so.6" //clone() is a function to create a new thread.
"#. 0x... start_thread () from /lib64/libpthread.so.0" //start_thread() is a function to start a poxis thread.

 

Summary

• pt-pmp is read-only tool and it depends on the linux gdb to collect stack traces.
• when pt-pmp works,it will attach gdb to the program you specified,what will probably freeze the program for a while.
• It's not recommend to run the tool on a very busy product system because of the potential freezing period and resource consumption.
• As a matter of fact,you can also do the stack tracing stuff by pstack tool but that's not today's motif.