• strace 命令


    strace 命令常用参数

    -tt 在每行输出的前面,显示毫秒级别的时间
    -T 显示每次系统调用所花费的时间
    -v 对于某些相关调用,把完整的环境变量,文件stat结构等打出来。
    -f 跟踪目标进程,以及目标进程创建的所有子进程
    -e 控制要跟踪的事件和跟踪行为,比如指定要跟踪的系统调用名称
    -o 把strace的输出单独写到指定的文件
    -s 当系统调用的某个参数是字符串时,最多输出指定长度的内容,默认是32个字节
    -p 指定要跟踪的进程pid, 要同时跟踪多个pid, 重复多次-p选项即可。

    系统调用主要分为几类:
    
    文件和设备访问类 比如open/close/read/write/chmod等
    进程管理类 fork/clone/execve/exit/getpid等
    信号类 signal/sigaction/kill 等
    内存管理 brk/mmap/mlock等
    进程间通信IPC shmget/semget * 信号量,共享内存,消息队列等
    网络通信 socket/connect/sendto/sendmsg 等
    其他
    
    -e trace=file     跟踪和文件访问相关的调用(参数中有文件名)
    -e trace=process  和进程管理相关的调用,比如fork/exec/exit_group
    -e trace=network  和网络通信相关的调用,比如socket/sendto/connect
    -e trace=signal    信号发送和处理相关,比如kill/sigaction
    -e trace=desc  和文件描述符相关,比如write/read/select/epoll等
    -e trace=ipc 进程见同学相关,比如shmget等
    
    

    strace命令主要用于跟踪用户态、内核态的系统调用,

    1、使用strace命令,观察MySQL启动过程

    篇幅有限,只截取了前边的一些内容,可以看到有很多调用,{brk mmap open close read 等} ,strace 命令默认只跟踪进程的系统调用,其中线程的调用并不会采集,如果要查看到线程的系统调用需要加参数 -f

    execve("bin/mysqld", ["bin/mysqld", "--defaults-file=/etc/my57.cnf", "--user=root"], 0x7ffd2fcf6460 /* 22 vars */) = 0
    brk(NULL)                               = 0x30d7000
    mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8097b0a000
    access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
    open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
    fstat(3, {st_mode=S_IFREG|0644, st_size=26180, ...}) = 0
    mmap(NULL, 26180, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f8097b03000
    close(3)                                = 0
    open("/lib64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
    read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200m\0\0\0\0\0\0"..., 832) = 832
    fstat(3, {st_mode=S_IFREG|0755, st_size=142144, ...}) = 0
    mmap(NULL, 2208904, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f80976ce000
    mprotect(0x7f80976e5000, 2093056, PROT_NONE) = 0
    mmap(0x7f80978e4000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16000) = 0x7f80978e4000
    mmap(0x7f80978e6000, 13448, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f80978e6000
    close(3)                                = 0
    open("/lib64/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
    read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\16\0\0\0\0\0\0"..., 832) = 832
    fstat(3, {st_mode=S_IFREG|0755, st_size=19248, ...}) = 0
    mmap(NULL, 2109744, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f80974ca000
    mprotect(0x7f80974cc000, 2097152, PROT_NONE) = 0
    mmap(0x7f80976cc000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f80976cc000
    close(3)                                = 0
    open("/lib64/libaio.so.1", O_RDONLY|O_CLOEXEC) = 3
    read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\5\0\0\0\0\0\0"..., 832) = 832
    fstat(3, {st_mode=S_IFREG|0755, st_size=6264, ...}) = 0
    mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8097b02000
    mmap(NULL, 2101328, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f80972c8000
    mprotect(0x7f80972c9000, 2093056, PROT_NONE) = 0
    mmap(0x7f80974c8000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0) = 0x7f80974c8000
    close(3)                                = 0
    open("/lib64/libnuma.so.1", O_RDONLY|O_CLOEXEC) = 3
    read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0004\0\0\0\0\0\0"..., 832) = 832
    fstat(3, {st_mode=S_IFREG|0755, st_size=50704, ...}) = 0
    mmap(NULL, 2144448, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f80970bc000
    mprotect(0x7f80970c6000, 2097152, PROT_NONE) = 0
    mmap(0x7f80972c6000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xa000) = 0x7f80972c6000
    close(3)                                = 0
    open("/lib64/libcrypt.so.1", O_RDONLY|O_CLOEXEC) = 3
    read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000\16\0\0\0\0\0\0"..., 832) = 832
    fstat(3, {st_mode=S_IFREG|0755, st_size=40600, ...}) = 0
    mmap(NULL, 2318912, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f8096e85000
    mprotect(0x7f8096e8d000, 2093056, PROT_NONE) = 0
    mmap(0x7f809708c000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x7f809708c000
    mmap(0x7f809708e000, 184896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f809708e000
    close(3)                                = 0
    open("/lib64/librt.so.1", O_RDONLY|O_CLOEXEC) = 3
    ......
    

    2、常用方法:

    strace -T -tt -s 100 -f -o start.log bin/mysqld --defaults-file=/etc/my57.cnf --user=root

    可以将各个线程的调用全部打印出来

    24885 02:49:42.393497 close(52)         = 0 <0.000034>
    24885 02:49:42.393672 mprotect(0x7f134095c000, 32768, PROT_READ|PROT_WRITE) = 0 <0.000030>
    24885 02:49:42.393963 stat("./ceshi/tt4.frm", {st_mode=S_IFREG|0640, st_size=8556, ...}) = 0 <0.000074>
    24885 02:49:42.394195 access("./ceshi/tt4.TRG", F_OK) = -1 ENOENT (No such file or directory) <0.000073>
    24885 02:49:42.394466 sendto(49, "'\0\0\1\3def\5ceshi\3tt4\3tt4\2id\2id\f?\0\v\0\0\0\3\3P\0\0\0\0010\7\0\0\2\376\0\0\2\0\0\0", 54, MSG_DONTWAIT, NULL, 0) = 54 <0.000143>
    24885 02:49:42.394803 recvfrom(49, "\5\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000038>
    24885 02:49:42.395001 recvfrom(49, "\4tt5\0", 5, MSG_DONTWAIT, NULL, NULL) = 5 <0.000041>
    24885 02:49:42.395248 open("./ceshi/tt5.frm", O_RDONLY) = 52 <0.000103>
    24885 02:49:42.395435 getcwd("/usr/local/mysql57/data", 4096) = 24 <0.000081>
    24885 02:49:42.395566 lstat("/usr/local/mysql57/data/ceshi", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0 <0.000084>
    24885 02:49:42.395734 read(52, "\376\1\t\f\3\0\0\20\1\0\0000\0\0i\1\5\0\0\0\0\0\0\0\0\0\0\2!\0\10\0\0\5\0\0\0\0!\0\0\0\0\0\0\0\0i\1\0\0.\306\0\0\36\0\0\0\0\0\0\0\0", 64) = 64 <0.000016>
    24885 02:49:42.395855 lseek(52, 64, SEEK_SET) = 64 <0.000032>
    24885 02:49:42.395996 read(52, "//\0\0 \0\0", 7) = 7 <0.000049>
    24885 02:49:42.396225 lseek(52, 8192, SEEK_SET) = 8192 <0.000023>
    24885 02:49:42.396474 read(52, "l\1\0\20\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 288) = 288 <0.000038>
    24885 02:49:42.396672 lseek(52, 4096, SEEK_SET) = 4096 <0.000017>
    24885 02:49:42.396797 read(52, "\1\1\0\0\n\0\0\0\4\0\1\0\0\0\1\200\2\0\0\33@\4\0\377PRIMARY\377\0", 33) = 33 <0.000016>
    24885 02:49:42.396906 pread64(52, "\0\0\6\0InnoDB\0\0\0\0\0\0\n\0\0\0\0\0\0\0\0\0\0\0\0\0", 30, 4462) = 30 <0.000042>
    24885 02:49:42.397024 pread64(52, "\377\0\0\0\0", 5, 4457) = 5 <0.000015>
    24885 02:49:42.397123 lseek(52, 8480, SEEK_SET) = 8480 <0.000014>
    24885 02:49:42.397218 read(52, "6\0\2\1\2\24)                                        \0\4\0\3id\0\4\3\v\v\0\2\0\0\33@\0\0\0\3!\0\0\377id\377\0", 76) = 76 <0.000014>
    24885 02:49:42.397348 close(52)         = 0 <0.000062>
    24885 02:49:42.397569 mprotect(0x7f1340964000, 4096, PROT_READ|PROT_WRITE) = 0 <0.000089>
    24885 02:49:42.397883 stat("./ceshi/tt5.frm", {st_mode=S_IFREG|0640, st_size=8556, ...}) = 0 <0.000065>
    24885 02:49:42.398063 access("./ceshi/tt5.TRG", F_OK) = -1 ENOENT (No such file or directory) <0.000047>
    24885 02:49:42.398410 sendto(49, "'\0\0\1\3def\5ceshi\3tt5\3tt5\2id\2id\f?\0\v\0\0\0\3\3P\0\0\0\0010\7\0\0\2\376\0\0\2\0\0\0", 54, MSG_DONTWAIT, NULL, 0) = 54 <0.000179>
    24885 02:49:42.398692 recvfrom(49, "\20\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4 <0.000063>
    24885 02:49:42.398850 recvfrom(49, "\3select * from t", 16, MSG_DONTWAIT, NULL, NULL) = 16 <0.000086>
    24885 02:49:42.399169 sendto(49, "\1\0\0\1\3!\0\0\2\3def\5ceshi\1t\1t\2id\2id\f?\0\v\0\0\0\3\3P\0\0\0\37\0\0\3\3def\5ceshi\1t\1t\1c\1c\f?\0\v\0\0\0\3\10@\0\0\0\37\0\0\4\3def\5ceshi\1t\1t\1d\1d\f"..., 195, MSG_DONTWAIT, NULL, 0) = 195 <0.000157>
    24885 02:49:42.399449 recvfrom(49,  <unfinished ...>
    24851 02:49:42.399537 <... io_getevents resumed>[], {tv_sec=0, tv_nsec=500000000}) = 0 <0.500114>
    24885 02:49:42.399628 <... recvfrom resumed>0x7f134000a210, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000151>
    24851 02:49:42.399658 io_getevents(0x7f1381a35000, 1, 256,  <unfinished ...>
    24885 02:49:42.399723 poll([{fd=49, events=POLLIN|POLLPRI}], 1, 7200000 <unfinished ...>
    24860 02:49:42.446576 <... nanosleep resumed>NULL) = 0 <1.000675>
    24858 02:49:42.446667 <... futex resumed>) = -1 ETIMEDOUT (Connection timed out) <1.000465>
    24857 02:49:42.446682 <... futex resumed>) = -1 ETIMEDOUT (Connection timed out) <1.000737>
    24860 02:49:42.446698 nanosleep({tv_sec=1, tv_nsec=0},  <unfinished ...>
    ......
    

    3、针对某类调用进行显示

    strace -T -tt -s 100 -f -e trace=file -o start.log bin/mysqld --defaults-file=/etc/my57.cnf --user=root

    结果显示,可以看到MySQL要打开【/ceshi/czg.TRG】文件,但报错没有这个文件,这个文件是触发器,只有该表上的触发器的时候,才会生成 trg 文件,由此可以看出,数据库打开文件时,不止打开ibd frm 文件,也会尝试打开 trg 文件,即使它不存在,日志中有许多类似报错,我只截取了其中一条####

    26870 03:26:46.620137 lstat("/usr/local/mysql57/data/172_16_1_10_3357_ceshi", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0 <0.000051>
    26870 03:26:46.620521 open("./inception/db.opt", O_RDONLY) = 50 <0.000064>
    26870 03:26:46.620676 getcwd("/usr/local/mysql57/data", 4096) = 24 <0.000069>
    26870 03:26:46.620846 lstat("/usr/local/mysql57/data/inception", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0 <0.000048>
    26870 03:26:46.621109 open("./mysql/db.opt", O_RDONLY) = 50 <0.000054>
    26870 03:26:46.621237 getcwd("/usr/local/mysql57/data", 4096) = 24 <0.000043>
    26870 03:26:46.621364 lstat("/usr/local/mysql57/data/mysql", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0 <0.000045>
    26870 03:26:46.621633 open("./performance_schema/db.opt", O_RDONLY) = 50 <0.000069>
    26870 03:26:46.621798 getcwd("/usr/local/mysql57/data", 4096) = 24 <0.000060>
    26870 03:26:46.622004 lstat("/usr/local/mysql57/data/performance_schema", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0 <0.000076>
    26870 03:26:46.622432 open("./sys/db.opt", O_RDONLY) = 50 <0.000082>
    26870 03:26:46.622699 getcwd("/usr/local/mysql57/data", 4096) = 24 <0.000060>
    26870 03:26:46.622878 lstat("/usr/local/mysql57/data/sys", {st_mode=S_IFDIR|0750, st_size=12288, ...}) = 0 <0.000048>
    26870 03:26:46.623650 openat(AT_FDCWD, "./ceshi/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 50 <0.000083>
    26870 03:26:46.624211 open("./ceshi/czg.frm", O_RDONLY) = 50 <0.000102>
    26870 03:26:46.624441 getcwd("/usr/local/mysql57/data", 4096) = 24 <0.000056>
    26870 03:26:46.624684 lstat("/usr/local/mysql57/data/ceshi", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0 <0.000075>
    26870 03:26:46.625414 stat("./ceshi/czg.frm", {st_mode=S_IFREG|0640, st_size=8556, ...}) = 0 <0.000082>
    26870 03:26:46.627994 access("./ceshi/czg.TRG", F_OK) = -1 ENOENT (No such file or directory) <0.000065>
    ......
    

    4、其它常用

    查看执行语句
    strace -f -F -ff -o mysqld-strace -s 1024 -p $mysqld_pid
    find ./ -name “mysqld-strace” -type f -print |xargs grep -n “SELECT.FROM”

    查看读写文件
    strace -o /tmp/strace_output.txt -T -tt -f -e trace=read,open -p “mysqld_pid”

    系统调用说明:(慢慢更新)####

  • 相关阅读:
    第九周学习进度总结
    SLR(1)语法分析(JAVA实现)
    算符优先分析
    第八周学习进度总结
    Android 自学之相对布局 RelativeLayout
    Android 自学之表格布局 TableLayout
    Android 自学之线性布局 LinearLayout
    Android 自学之帧布局 FrameLayout
    机器学习进度05(FaceBook案例)
    机器学习进度04(转换器、预估器、K-近邻算法、模式选择与调优)
  • 原文地址:https://www.cnblogs.com/nanxiang/p/16009350.html
Copyright © 2020-2023  润新知