如何找出瘋狂打日志的進程

啟動案例應(yīng)用

docker run -v /tmp:/tmp --name=app -itd feisky/logapp

用 top 命令觀察cpu，內(nèi)存等使用情況

top - 07:37:52 up 7 min,  1 user,  load average: 2.74, 1.27, 0.52
Tasks: 116 total,   2 running,  56 sleeping,   0 stopped,   0 zombie
%Cpu(s):  3.6 us,  7.7 sy,  0.0 ni, 10.1 id, 78.6 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  3760660 total,   147584 free,  1160440 used,  2452636 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  2333960 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
11747 root      20   0  963312 934344   5320 D  24.9 24.8   0:36.05 python
   76 root      20   0       0      0      0 D   0.9  0.0   0:01.93 kworker/u4:2+fl
   67 root       0 -20       0      0      0 I   0.4  0.0   0:00.28 kworker/0:1H-kb

發(fā)現(xiàn)系統(tǒng) iowait 快速比較高。并且內(nèi)存大部分被buff/cache占用。

繼續(xù)用 iostat 觀察磁盤 io 情況

# -d表示顯示I/O性能指標，-x表示顯示擴展統(tǒng)計（即所有I/O指標）
iostat -x -d 1
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
vda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
vdb               0.00     0.00    0.00  260.00     0.00 116856.00   898.89   107.16  412.65    0.00  412.65   3.84  99.90

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
vda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
vdb               0.00     0.00    0.00  236.00     0.00 118256.00  1002.17   128.66  545.65    0.00  545.65   4.24 100.00

發(fā)現(xiàn)磁盤 sdb 使用率已經(jīng)達到接近100%。

繼續(xù)用 pidstat 觀察進程的 io 占用情況

# pidstat 加上 -d 參數(shù)，就可以顯示每個進程的 I/O 情況
pidstat -d 1
07:40:11 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
07:40:12 AM     0     11747      0.00  72672.00      0.00  python

07:40:13 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
07:40:14 AM     0     11166      0.00     28.00      0.00  jbd2/vdb-8
07:40:14 AM     0     11747      0.00 176160.00      0.00  python
07:40:14 AM     0     13266      0.00      4.00      0.00  sap1002

可以發(fā)現(xiàn)，我們找到了占用內(nèi)存比較高的進程，應(yīng)該是這里的 python 程序。

用 strace 追蹤具體的進程。

strace -p 11747
strace: Process 11747 attached
munmap(0x7fcfcbbde000, 314576896)       = 0
write(3, "\n", 1)                       = 1
munmap(0x7fcfde7df000, 314576896)       = 0
select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=100000}) = 0 (Timeout)
getpid()                                = 1
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfde7df000
mmap(NULL, 393220096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfc70de000
mremap(0x7fcfc70de000, 393220096, 314576896, MREMAP_MAYMOVE) = 0x7fcfc70de000
munmap(0x7fcfde7df000, 314576896)       = 0
lseek(3, 0, SEEK_END)                   = 629145690
lseek(3, 0, SEEK_CUR)                   = 629145690
munmap(0x7fcfc70de000, 314576896)       = 0
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfde7df000
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfcbbde000
write(3, "2024-01-29 23:42:44,016 - __main"..., 314572844) = 314572844
munmap(0x7fcfcbbde000, 314576896)       = 0
write(3, "\n", 1)                       = 1
munmap(0x7fcfde7df000, 314576896)       = 0
select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=100000}) = 0 (Timeout)
getpid()                                = 1
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfde7df000
mmap(NULL, 393220096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfc70de000
mremap(0x7fcfc70de000, 393220096, 314576896, MREMAP_MAYMOVE) = 0x7fcfc70de000
munmap(0x7fcfde7df000, 314576896)       = 0
lseek(3, 0, SEEK_END)                   = 943718535
lseek(3, 0, SEEK_CUR)                   = 943718535
munmap(0x7fcfc70de000, 314576896)       = 0
close(3)                                = 0
stat("/tmp/logtest.txt.1", {st_mode=S_IFREG|0644, st_size=943718535, ...}) = 0
unlink("/tmp/logtest.txt.1")            = 0
stat("/tmp/logtest.txt", {st_mode=S_IFREG|0644, st_size=943718535, ...}) = 0
rename("/tmp/logtest.txt", "/tmp/logtest.txt.1") = 0
open("/tmp/logtest.txt", O_WRONLY|O_CREAT|O_APPEND|O_CLOEXEC, 0666) = 3
fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
lseek(3, 0, SEEK_END)                   = 0

從 write() 系統(tǒng)調(diào)用上，我們可以看到，進程向文件描述符編號為 3 的文件中，寫入了 300MB 的數(shù)據(jù)?？吹揭粋€日志文件路徑/tmp/logtest.txt.1，可以猜測，這是一個日志回滾文件，而正在寫的日志文件路徑，則是 /tmp/logtest.txt。

可以繼續(xù)用 lsof 查看這個進程打開了哪些文件。

lsof -p 11747
COMMAND   PID USER   FD   TYPE DEVICE  SIZE/OFF   NODE NAME
python  11747 root  cwd    DIR   0,47      4096 661078 /
python  11747 root  rtd    DIR   0,47      4096 661078 /
python  11747 root    2u   CHR  136,0       0t0      3 /dev/pts/0
python  11747 root    3w   REG 253,16 244989952     14 /tmp/logtest.txt

至此，我們已經(jīng)確認進程 11747 以每次 300MB 的速度，在“瘋狂”寫日志，而日志文件的路徑是 /tmp/logtest.txt。

SQL查詢磁盤性能分析

使用 top 命令查看服務(wù)器的負載

top
top - 12:02:15 up 6 days,  8:05,  1 user,  load average: 0.66, 0.72, 0.59
Tasks: 137 total,   1 running,  81 sleeping,   0 stopped,   0 zombie
%Cpu0  :  0.7 us,  1.3 sy,  0.0 ni, 35.9 id, 62.1 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  :  0.3 us,  0.7 sy,  0.0 ni, 84.7 id, 14.3 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  8169300 total,  7238472 free,   546132 used,   384696 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  7316952 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
27458 999       20   0  833852  57968  13176 S   1.7  0.7   0:12.40 mysqld

可以看到 cpu0 的 iowait 比較高

查看磁盤使用情況

$ iostat -d -x 1
Device            r/s     w/s     rkB/s     wkB/s   rrqm/s   wrqm/s  %rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz  svctm  %util
...
sda            273.00    0.00  32568.00      0.00     0.00     0.00   0.00   0.00    7.90    0.00   1.16   119.30     0.00   3.56  97.20

可以看到，磁盤 sda 有大量的讀操作，并且使用率也幾乎打滿。

使用 pidstat 查看具體進程的 io 使用情況

pidstat -d 1
12:04:11      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
12:04:12      999     27458  32640.00      0.00      0.00       0  mysqld
12:04:12        0     27617      4.00      4.00      0.00       3  python
12:04:12        0     27864      0.00      4.00      0.00       0  systemd-journal

定位到了 mysqld 進程。

使用 strace 命令定位 mysql 進程的數(shù)據(jù)讀取情況，加上-f 參數(shù)

strace -f -p 27458
[pid 28014] read(38, "934EiwT363aak7VtqF1mHGa4LL4Dhbks"..., 131072) = 131072
[pid 28014] read(38, "hSs7KBDepBqA6m4ce6i6iUfFTeG9Ot9z"..., 20480) = 20480
[pid 28014] read(38, "NRhRjCSsLLBjTfdqiBRLvN9K6FRfqqLm"..., 131072) = 131072
[pid 28014] read(38, "AKgsik4BilLb7y6OkwQUjjqGeCTQTaRl"..., 24576) = 24576
[pid 28014] read(38, "hFMHx7FzUSqfFI22fQxWCpSnDmRjamaW"..., 131072) = 131072
[pid 28014] read(38, "ajUzLmKqivcDJSkiw7QWf2ETLgvQIpfC"..., 20480) = 20480

可以看到，mysql 進程有大量線程在大量讀取。

使用 lsof 查看具體是打開了哪些文件

 lsof -p 27458
COMMAND  PID USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
...
mysqld  27458      999   38u   REG    8,1 512440000 2601895 /var/lib/mysql/test/products.MYD

可以看到正在讀的是 mysql 數(shù)據(jù)文件。

登錄 mysql，并且多觸發(fā)幾次查詢慢的任務(wù)，可以看到正在執(zhí)行的是哪些 sql, 為了保證 SQL 語句不截斷，這里可以執(zhí)行 show full processlist 命令

mysql> show full processlist;
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
| Id | User | Host            | db   | Command | Time | State        | Info                                                |
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
| 27 | root | localhost       | test | Query   |    0 | init         | show full processlist                               |
| 28 | root | 127.0.0.1:42262 | test | Query   |    1 | Sending data | select * from products where productName='geektime' |
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
2 rows in set (0.00 sec)

使用 explain 語句分析有問題的 sql

# 切換到test庫
mysql> use test;
# 執(zhí)行explain命令
mysql> explain select * from products where productName='geektime';
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
| id | select_type | table    | type | possible_keys | key  | key_len | ref  | rows  | Extra       |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
|  1 | SIMPLE      | products | ALL  | NULL          | NULL | NULL    | NULL | 10000 | Using where |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
1 row in set (0.00 sec)

其中，有幾個比較重要的字段需要注意

select_type 表示查詢類型，而這里的 SIMPLE 表示此查詢不包括 UNION 查詢或者子查詢；
table 表示數(shù)據(jù)表的名字，這里是 products；
type 表示查詢類型，這里的 ALL 表示全表查詢，但索引查詢應(yīng)該是 index 類型才對；
possible_keys 表示可能選用的索引，這里是 NULL；
key 表示確切會使用的索引，這里也是 NULL；
rows 表示查詢掃描的行數(shù)，這里是 10000。
根據(jù)結(jié)果，我們可以確定，這條查詢語句壓根兒沒有使用索引，所以查詢時，會掃描全表，并且掃描行數(shù)高達 10000 行。響應(yīng)速度肯定會很慢。

優(yōu)化方法：給productName字段添加 index 即可。

mysql> CREATE INDEX products_index ON products (productName(64));
Query OK, 10000 rows affected (14.45 sec)
Records: 10000  Duplicates: 0  Warnings: 0

色偷偷精品伊人,欧洲久久精品,欧美综合婷婷骚逼,国产AV主播,国产最新探花在线,九色在线视频一区,伊人大交九欧美,1769亚洲,黄色成人av

Linux I/O 性能分析思路

Linux I/O 性能分析思路

如何找出瘋狂打日志的進程

SQL查詢磁盤性能分析

相關(guān)閱讀更多精彩內(nèi)容

友情鏈接更多精彩內(nèi)容

色偷偷精品伊人,欧洲久久精品,欧美综合婷婷骚逼,国产AV主播,国产最新探花在线,九色在线视频一区,伊人大交九 欧美,1769亚洲,黄色成人av

Linux I/O 性能分析思路

如何找出瘋狂打日志的進程

SQL查詢磁盤性能分析

相關(guān)閱讀更多精彩內(nèi)容

友情鏈接更多精彩內(nèi)容

色偷偷精品伊人,欧洲久久精品,欧美综合婷婷骚逼,国产AV主播,国产最新探花在线,九色在线视频一区,伊人大交九欧美,1769亚洲,黄色成人av