mdl 锁 SYSTEMTAP跟踪
systemtap :
各种资源的使用限制由所生成的C代码中的宏来设置。这些值可在编译时由-D选项来重写。下面描述了部分挑选出来的宏： MAXNESTING 递归函数的最大调用层数，默认值是10。 MAXSTRINGLEN 字符串的最大长度，默认值是128。 MAXTRYLOCK 在声称可以出现死锁和跳出探测点前，等待全局变量锁的最大迭代次数，默认值是1000。 MAXACTION 单个探测点内可以执行语句数的最大值，默认值是1000。 MAXMAPENTRIES 数组在声明时没有显示指定大小时，数组的最大行数（译者注：即组数的最大下标个数），默认值为2048。 MAXERRORS 在触发退出前，可以容忍软件错误个数的最大值，默认值是0。 MAXSKIPPED 在触发退出前，可忽略的重入探测点的最大值，默认值是100。 MINSTACKSPACE 运行探测处理函数所需要的内核栈的最小字节数。此数值应比探测处理函数所需内核栈的大小加上安全边界大小足够大。默认值是1024。 Stap或statrun如果在探测点已经运行之后出现问题，可以安全杀死(kill)用户空间进程，并且可以使用rmmod命令删除内核探测模块。任何未处理的跟踪消息将丢失。
变量的引用有两种风格： $varname // 引用变量varname $var->field // 引用结构的成员变量 $var[N] // 引用数组的元素 &$var // 变量的地址 @var("varname") // 引用变量varname @var("var@src/file.c") // 引用src/file.c在被编译时的全局变量varname @var("varname@file.c")->field // 引用结构的成员变量 @var("var@file.c")[N] // 引用数组的元素 &@var("var@file.c") // 变量的地址 $var$ // provide a string that includes the values of basic type values $var$$ // provide a string that includes all values of nested data types $$vars // 一个包含所有函数参数、局部变量的字符串 $$locals // 一个包含所有局部变量的字符串 $$params // 一个包含所有函数参数的字符串
[root@localhost bin]# stap -L 'process("/usr/local/mysql56/bin/mysqld").function("MDL_context::acquire_lock")'
process("/usr/local/mysql56/bin/mysqld").function("MDL_context::acquire_lock@/usr/src/mysql-5.6.28/sql/mdl.cc:2184") $this:class MDL_context* const $mdl_request:class MDL_request* $lock_wait_timeout:ulong $lock:struct MDL_lock* $ticket:struct MDL_ticket* $abs_timeout:struct timespec $wait_status:enum enum_wait_status $__PRETTY_FUNCTION__:char[] const
基于源代码函数:
[root@localhost bin]# stap -v -g -d /usr/local/mysql56/bin/mysqld --ldd -e 'probe process("/usr/local/mysql56/bin/mysqld").function("MDL_context::acquire_lock") { printf("got it\n");print_ubacktrace();mdelay(10000) }'|c++filt
打印函数参数变量
会话1：
mysql> insert into uu select 1;
会话2：
[root@localhost bin]# stap -v -g -D MAXSTRINGLEN=1000 -d /usr/local/mysql56/bin/mysqld --ldd -e 'probe process("/usr/local/mysql56/bin/mysqld").function("MDL_context::acquire_lock") { printf("%s\n %s\n",probefunc(),$$parms$$);mdelay(1000) }'|c++filt
MDL_context::acquire_lock(MDL_request*, unsigned long) this={.m_wait={.m_LOCK_wait_status={.m_mutex={.global={.__data={.__lock=0, .__count=0, .__owner=0, .__nusers=0, .__kind=2, .__spins=0, .__list={.__prev=0x0, .__next=0x0}}, .__size="", .__align=0}, .mutex={.__data={.__lock=0, .__count=0, .__owner=0, .__nusers=0, .__kind=0, .__spins=0, .__list={.__prev=0x0, .__next=0x0}}, .__size="", .__align=0}, .file="/usr/src/mysql-5.6.28/sql/mdl.cc", .line=1239, .count=0, .thread=0}, .m_psi=0x0}, .m_COND_wait_status={.m_cond={.__data={.__lock=0, .__futex=0, .__total_seq=0, .__wakeup_seq=0, .__woken_seq=0, .__mutex=0x0, .__nwaiters=0, ...}, ...}, ...}, ...}, ...}
mdl_request={.type=0, .duration=0, .next_in_list=0xff2c7a, .prev_in_list=0x1e13380, .ticket=0x0,
.key={.m_length=3, .m_db_name_length=0, .m_ptr=""
}
} lock_wait_timeout=31536000
MDL_context::acquire_lock(MDL_request*, unsigned long) this={.m_wait={.m_LOCK_wait_status={.m_mutex={.global={.__data={.__lock=0, .__count=0, .__owner=0, .__nusers=0, .__kind=2, .__spins=0, .__list={.__prev=0x0, .__next=0x0}}, .__size="", .__align=0}, .mutex={.__data={.__lock=0, .__count=0, .__owner=0, .__nusers=0, .__kind=0, .__spins=0, .__list={.__prev=0x0, .__next=0x0}}, .__size="", .__align=0}, .file="/usr/src/mysql-5.6.28/sql/mdl.cc", .line=1239, .count=0, .thread=0}, .m_psi=0x0}, .m_COND_wait_status={.m_cond={.__data={.__lock=0, .__futex=0, .__total_seq=0, .__wakeup_seq=0, .__woken_seq=0, .__mutex=0x0, .__nwaiters=0, ...}, ...}, ...}, ...}, ...}
mdl_request={.type=4, .duration=1, .next_in_list=0x0, .prev_in_list=0x0, .ticket=0x0, .key={.m_length=9, .m_db_name_length=4, .m_ptr="test"}} lock_wait_timeout=31536000
MDL_context::acquire_lock(MDL_request*, unsigned long) this={.m_wait={.m_LOCK_wait_status={.m_mutex={.global={.__data={.__lock=0, .__count=0, .__owner=0, .__nusers=0, .__kind=2, .__spins=0, .__list={.__prev=0x0, .__next=0x0}}, .__size="", .__align=0}, .mutex={.__data={.__lock=0, .__count=0, .__owner=0, .__nusers=0, .__kind=0, .__spins=0, .__list={.__prev=0x0, .__next=0x0}}, .__size="", .__align=0}, .file="/usr/src/mysql-5.6.28/sql/mdl.cc", .line=1239, .count=0, .thread=0}, .m_psi=0x0}, .m_COND_wait_status={.m_cond={.__data={.__lock=0, .__futex=0, .__total_seq=0, .__wakeup_seq=0, .__woken_seq=0, .__mutex=0x0, .__nwaiters=0, ...}, ...}, ...}, ...}, ...}
mdl_request={.type=0, .duration=2, .next_in_list=0x1000000ab7cbe, .prev_in_list=0xf2f3bb, .ticket=0x0, .key={.m_length=3, .m_db_name_length=0, .m_ptr=""}} lock_wait_timeout=31536000
打印局部变量:
会话1：
mysql> insert into uu select 1;
会话2:
[root@localhost bin]# stap -v -g -D MAXSTRINGLEN=10000 -d /usr/local/mysql56/bin/mysqld --ldd -e 'probe process("/usr/local/mysql56/bin/mysqld").function("MDL_context::acquire_lock") { printf("%s\n %s\n",probefunc(),$$locals$$);mdelay(1000) }'|c++filt
MDL_context::acquire_lock(MDL_request*, unsigned long) lock={.key={.m_length=23416, .m_db_name_length=118, .m_ptr=""}, .m_rwlock={.m_prlock={.lock={.__data={.__lock=-2147483641, .__count=11063, .__owner=336330448, .__nusers=11063, .__kind=336329584, .__spins=11063, .__list={.__prev=0x76b4ad, .__next=0xf27abd}}, .__size="", .__align=47517370679303}, .no_active_readers={.__data={.__lock=336330112, .__futex=11063, .__total_seq=47515559525920, .__wakeup_seq=7732635, .__woken_seq=47515559525296, .__mutex=0x100000000e3ed37, .__nwaiters=0, .__broadcast_seq=0}, .__size="7+", .__align=47515559525760}, .active_readers=14923504, .writers_waiting_readers=0, .active_writer='\001', .writer_thread=36577248}, .m_psi=0x1e13380}, .m_granted={.m_list={.m_first=0x25b3cd0, .m_last=0x0}, .m_bitmap=32624}, .m_waiting={.m_list={.m_first=0x14f600e3ed37, ...}, ...}, ...} ticket={.next_in_context=0x22e1ec0, .prev_in_context=0x1e13380, .next_in_lock=0xab7bcf, .prev_in_lock=0xff01ac, .m_type=36576960, .m_duration=0, .m_ctx=0x2b37140bfab0, .m_lock=0xab7cbe} abs_timeout={.tv_sec=15799875, .tv_nsec=15799875} wait_status=0 __PRETTY_FUNCTION__="bool MDL_context::acquire_lock(MDL_request*, ulong)"
MDL_context::acquire_lock(MDL_request*, unsigned long) lock=ERROR ticket={.next_in_context=0x8b48e87d894820ec, .prev_in_context=0xc08548009ff3c305, .next_in_lock=0x8948e8458b480b75, .prev_in_lock=0xfdcee8009ff3b305, .m_type=2303262719, .m_duration=2202597445, .m_ctx=0x558b480b7400f87d, .m_lock=0x28948e8458b48f8} abs_timeout={.tv_sec=47515559524160, .tv_nsec=14937399} wait_status=0 __PRETTY_FUNCTION__="bool MDL_context::acquire_lock(MDL_request*, ulong)"
MDL_context::acquire_lock(MDL_request*, unsigned long) lock={.key={.m_length=46417, .m_db_name_length=238, .m_ptr=""}, .m_rwlock={.m_prlock={.lock={.__data={.__lock=36579824, .__count=0, .__owner=36575248, .__nusers=0, .__kind=0, .__spins=0, .__list={.__prev=0xc1, .__next=0x100000}}, .__size="", .__align=36579824}, .no_active_readers={.__data={.__lock=0, .__futex=0, .__total_seq=0, .__wakeup_seq=47515464583488, .__woken_seq=36524160, .__mutex=0x22d77c0, .__nwaiters=36604680, .__broadcast_seq=0}, .__size="", .__align=0}, .active_readers=36616120, .writers_waiting_readers=0, .active_writer='\000', .writer_thread=0}, .m_psi=0x0}, .m_granted={.m_list={.m_first=0x0, .m_last=0x384}, .m_bitmap=0}, .m_waiting={.m_list={.m_first=0x1058783, ...}, ...}, ...} ticket={.next_in_context=0x10000022e1ec0, .prev_in_context=0x2b37140bfbb0, .next_in_lock=0xe3ed37, .prev_in_lock=0x22e1fe0, .m_type=14923504, .m_duration=0, .m_ctx=0x100000000000001, .m_lock=0x22e1fe0} abs_timeout={.tv_sec=47515559525088, .tv_nsec=14923147} wait_status=0 __PRETTY_FUNCTION__="bool MDL_context::acquire_lock(MDL_request*, ulong)"
打印局部变量+函数参数变量
MDL_context::acquire_lock(MDL_request*, unsigned long) this={.m_wait={.m_LOCK_wait_status={.m_mutex={.global={.__data={.__lock=0, .__count=0, .__owner=0, .__nusers=0, .__kind=2, .__spins=0, .__list={.__prev=0x0, .__next=0x0}}, .__size="", .__align=0}, .mutex={.__data={.__lock=0, .__count=0, .__owner=0, .__nusers=0, .__kind=0, .__spins=0, .__list={.__prev=0x0, .__next=0x0}}, .__size="", .__align=0}, .file="/usr/src/mysql-5.6.28/sql/mdl.cc", .line=1239, .count=0, .thread=0}, .m_psi=0x0}, .m_COND_wait_status={.m_cond={.__data={.__lock=0, .__futex=0, .__total_seq=0, .__wakeup_seq=0, .__woken_seq=0, .__mutex=0x0, .__nwaiters=0, ...}, ...}, ...}, ...}, ...} mdl_request={.type=0, .duration=0, .next_in_list=0xff2c7a, .prev_in_list=0x1e13380, .ticket=0x0, .key={.m_length=3, .m_db_name_length=0, .m_ptr=""}} lock_wait_timeout=31536000 lock={.key={.m_length=23416, .m_db_name_length=118, .m_ptr=""}, .m_rwlock={.m_prlock={.lock={.__data={.__lock=-2147483641, .__count=11063, .__owner=336330448, .__nusers=11063, .__kind=336329584, .__spins=11063, .__list={.__prev=0x76b4ad, .__next=0xf27abd}}, .__size="", .__align=47517370679303}, .no_active_readers={.__data={.__lock=336330112, .__futex=11063, .__total_seq=47515559525920, .__wakeup_seq=7732635, .__woken_seq=47515559525296, .__mutex=0x100000000e3ed37, .__nwaiters=0, .__broadcast_seq=0}, .__size="7+", .__align=47515559525760}, .active_readers=14923504, .writers_waiting_readers=0, .active_writer='\001', .writer_thread=36577248}, .m_psi=0x1e13380}, .m_granted={.m_list={.m_first=0x25b3cd0, .m_last=0x0}, .m_bitmap=32624}, .m_waiting={.m_list={.m_first=0x14f600e3ed37, ...}, ...}, ...} ticket={.next_in_context=0x22e1ec0, .prev_in_context=0x1e13380, .next_in_lock=0xab7bcf, .prev_in_lock=0xff01ac, .m_type=36576960, .m_duration=0, .m_ctx=0x2b37140bfab0, .m_lock=0xab7cbe} abs_timeout={.tv_sec=15799875, .tv_nsec=15799875} wait_status=0 __PRETTY_FUNCTION__="bool MDL_context::acquire_lock(MDL_request*, ulong)"
MDL_context::acquire_lock(MDL_request*, unsigned long) this={.m_wait={.m_LOCK_wait_status={.m_mutex={.global={.__data={.__lock=0, .__count=0, .__owner=0, .__nusers=0, .__kind=2, .__spins=0, .__list={.__prev=0x0, .__next=0x0}}, .__size="", .__align=0}, .mutex={.__data={.__lock=0, .__count=0, .__owner=0, .__nusers=0, .__kind=0, .__spins=0, .__list={.__prev=0x0, .__next=0x0}}, .__size="", .__align=0}, .file="/usr/src/mysql-5.6.28/sql/mdl.cc", .line=1239, .count=0, .thread=0}, .m_psi=0x0}, .m_COND_wait_status={.m_cond={.__data={.__lock=0, .__futex=0, .__total_seq=0, .__wakeup_seq=0, .__woken_seq=0, .__mutex=0x0, .__nwaiters=0, ...}, ...}, ...}, ...}, ...} mdl_request={.type=4, .duration=1, .next_in_list=0x0, .prev_in_list=0x0, .ticket=0x0, .key={.m_length=9, .m_db_name_length=4, .m_ptr="test"}} lock_wait_timeout=31536000 lock=ERROR ticket={.next_in_context=0x8b48e87d894820ec, .prev_in_context=0xc08548009ff3c305, .next_in_lock=0x8948e8458b480b75, .prev_in_lock=0xfdcee8009ff3b305, .m_type=2303262719, .m_duration=2202597445, .m_ctx=0x558b480b7400f87d, .m_lock=0x28948e8458b48f8} abs_timeout={.tv_sec=47515559524160, .tv_nsec=14937399} wait_status=0 __PRETTY_FUNCTION__="bool MDL_context::acquire_lock(MDL_request*, ulong)"
MDL_context::acquire_lock(MDL_request*, unsigned long) this={.m_wait={.m_LOCK_wait_status={.m_mutex={.global={.__data={.__lock=0, .__count=0, .__owner=0, .__nusers=0, .__kind=2, .__spins=0, .__list={.__prev=0x0, .__next=0x0}}, .__size="", .__align=0}, .mutex={.__data={.__lock=0, .__count=0, .__owner=0, .__nusers=0, .__kind=0, .__spins=0, .__list={.__prev=0x0, .__next=0x0}}, .__size="", .__align=0}, .file="/usr/src/mysql-5.6.28/sql/mdl.cc", .line=1239, .count=0, .thread=0}, .m_psi=0x0}, .m_COND_wait_status={.m_cond={.__data={.__lock=0, .__futex=0, .__total_seq=0, .__wakeup_seq=0, .__woken_seq=0, .__mutex=0x0, .__nwaiters=0, ...}, ...}, ...}, ...}, ...} mdl_request={.type=0, .duration=2, .next_in_list=0x1000000ab7cbe, .prev_in_list=0xf2f3bb, .ticket=0x0, .key={.m_length=3, .m_db_name_length=0, .m_ptr=""}} lock_wait_timeout=31536000 lock={.key={.m_length=46417, .m_db_name_length=238, .m_ptr=""}, .m_rwlock={.m_prlock={.lock={.__data={.__lock=36579824, .__count=0, .__owner=36575248, .__nusers=0, .__kind=0, .__spins=0, .__list={.__prev=0xc1, .__next=0x100000}}, .__size="", .__align=36579824}, .no_active_readers={.__data={.__lock=0, .__futex=0, .__total_seq=0, .__wakeup_seq=47515464583488, .__woken_seq=36524160, .__mutex=0x22d77c0, .__nwaiters=36604680, .__broadcast_seq=0}, .__size="", .__align=0}, .active_readers=36616120, .writers_waiting_readers=0, .active_writer='\000', .writer_thread=0}, .m_psi=0x0}, .m_granted={.m_list={.m_first=0x0, .m_last=0x384}, .m_bitmap=0}, .m_waiting={.m_list={.m_first=0x1058783, ...}, ...}, ...} ticket={.next_in_context=0x10000022e1ec0, .prev_in_context=0x2b37140bfbb0, .next_in_lock=0xe3ed37, .prev_in_lock=0x22e1fe0, .m_type=14923504, .m_duration=0, .m_ctx=0x100000000000001, .m_lock=0x22e1fe0} abs_timeout={.tv_sec=47515559525088, .tv_nsec=14923147} wait_status=0 __PRETTY_FUNCTION__="bool MDL_context::acquire_lock(MDL_request*, ulong)"
打印其中的某个变量值的内部某个成员
会话1:
mysql> insert into uu select 1;
会话2：
[root@localhost bin]# stap -v -g -D MAXSTRINGLEN=10000 -d /usr/local/mysql56/bin/mysqld --ldd -e 'probe process("/usr/local/mysql56/bin/mysqld").function("MDL_context::acquire_lock") { printf("%s\n %d\n",probefunc(),$mdl_request->type);mdelay(1000) }'|c++filt
MDL_context::acquire_lock(MDL_request*, unsigned long) 0 MDL_context::acquire_lock(MDL_request*, unsigned long) 4 MDL_context::acquire_lock(MDL_request*, unsigned long) 0
打印其中的某个变量值的全部成员:
会话1:
mysql> insert into uu select 1;
会话2：
[root@localhost bin]# stap -v -g -D MAXSTRINGLEN=10000 -d /usr/local/mysql56/bin/mysqld --ldd -e 'probe process("/usr/local/mysql56/bin/mysqld").function("MDL_context::acquire_lock") { printf("%s\n %s\n",probefunc(),$mdl_request$$);mdelay(1000) }'|c++filt
MDL_context::acquire_lock(MDL_request*, unsigned long) {.type=0, .duration=0, .next_in_list=0xff2c7a, .prev_in_list=0x1e13380, .ticket=0x0, .key={.m_length=3, .m_db_name_length=0, .m_ptr=""}}
MDL_context::acquire_lock(MDL_request*, unsigned long) {.type=4, .duration=1, .next_in_list=0x0, .prev_in_list=0x0, .ticket=0x0, .key={.m_length=9, .m_db_name_length=4, .m_ptr="test"}}
MDL_context::acquire_lock(MDL_request*, unsigned long) {.type=0, .duration=2, .next_in_list=0x1000000ab7cbe, .prev_in_list=0xf2f3bb, .ticket=0x0, .key={.m_length=3, .m_db_name_length=0, .m_ptr=""}} ^CPass 5: run completed in 10usr/80sys/23132real ms.
[root@localhost bin]# stap -v -g -D MAXSTRINGLEN=10000 -d /usr/local/mysql56/bin/mysqld --ldd -e 'probe process("/usr/local/mysql56/bin/mysqld").function("MDL_request::MDL_request") { printf("%s\n %s\n",probefunc(),$$parms$$);mdelay(10000) }'|c++filt
MDL_request::MDL_request() this={.type=0, .duration=0, .next_in_list=0x0, .prev_in_list=0x14edc50, .ticket=0x25a7f70, .key={.m_length=0, .m_db_name_length=0, .m_ptr=""}}
MDL_request::MDL_request() this={.type=39485296, .duration=0, .next_in_list=0x0, .prev_in_list=0x0, .ticket=0x0, .key={.m_length=13184, .m_db_name_length=481, .m_ptr=""}}
MDL_request::MDL_request() this=ERROR
MDL_request::MDL_request() this={.type=1213580233, .duration=2202592649, .next_in_list=0x8b48e87d894820ec, .prev_in_list=0xc08548009ff3c305, .ticket=0x8948e8458b480b75, .key={.m_length=45829, .m_db_name_length=40947, .m_ptr=""}}
MDL_request::MDL_request() this={.type=2486623075, .duration=32767, .next_in_list=0xeeb551, .prev_in_list=0xee97d0, .ticket=0x2b37140bfd40, .key={.m_length=44352, .m_db_name_length=387, .m_ptr=""}}
MDL_request::MDL_request() this={.type=1213580233, .duration=2202592649, .next_in_list=0x8b48e87d894820ec, .prev_in_list=0xc08548009ff3c305, .ticket=0x8948e8458b480b75, .key={.m_length=45829, .m_db_name_length=40947, .m_ptr=""}}
