文章目录提示：文章写完后，目录可以自动生成，如何生成可参考右边的帮助文档
- 前言
- 一、io问题分析
- 总结
前言
在某次实验环境中，发现我的达梦数据库环境top下us跟sys的使用率都有点高，并且伴随着一些iowait情况，随后就针对本次内容，进行一个初步尝试分析
一、io问题分析
可以看到，当前环境下我的sys跟iowait都有点高，那么是什么导致的呢，我们往下分析
随后我们使用vmstat工具分析下上下文切换情况，发现in跟cs的值都很大，尤其是cs每秒上下文切换次数非常高，但是具体是什么导致的目前我们还不知道，所以我们继续分析下
[root@dmsh1 tools]# vmstat 1 5 procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 12 0 0 115000 0 1287496 0 0 1225 2976 1553 2269 20 23 51 6 0 10 0 0 117388 0 1286568 0 0 4744 16353 9712 37034 21 77 2 1 0 8 0 0 114640 0 1287908 0 0 4708 45482 9487 29766 18 70 7 6 0 11 0 0 114972 0 1287960 0 0 5908 18971 9904 35690 16 77 7 1 0 9 1 0 113908 0 1288812 0 0 6580 29369 9848 39746 21 77 2 1 0
随后我们使用pidstat 工具分析下，pidstat 用于监控全部或指定进程占用系统资源的情况，如CPU，内存、设备IO、任务切换、线程等
发现dm的sql线程的每秒自愿上下文切换跟非自愿上下文切换的值都比较大，
自愿上下文切换cswch/s也就意味着进程无法获取所需资源，常见的io、内存等系统资源不足会发生这类问题
非资源上下文切换nvcswch/s指进程由于时间片已到等原因被系统强制调度，比如大量进程都在争抢cpu就容易发生非自愿
[root@dmsh1 tools]# pidstat -w -t 1 Linux 5.18.3-1.el7.elrepo.x86_64 (dmsh1) 2022年06月13日 _x86_64_ (2 CPU) 12时50分52秒 UID TGID TID cswch/s nvcswch/s Command 12时50分53秒 0 9 - 1150.93 0.00 kworker/0:1H-kblockd 12时50分53秒 0 - 9 1150.93 0.00 |__kworker/0:1H-kblockd 12时50分53秒 0 14 - 12.04 0.00 ksoftirqd/0 12时50分53秒 0 - 14 12.04 0.00 |__ksoftirqd/0 12时50分53秒 0 15 - 62.04 0.00 rcu_preempt 12时50分53秒 0 - 15 62.04 0.00 |__rcu_preempt 12时50分53秒 0 21 - 143.52 0.00 ksoftirqd/1 12时50分53秒 0 - 21 143.52 0.00 |__ksoftirqd/1 12时50分53秒 0 45 - 571.30 0.00 kworker/1:1H-kblockd 12时50分53秒 0 - 45 571.30 0.00 |__kworker/1:1H-kblockd 12时50分53秒 0 46 - 1.85 1.85 kswapd0 12时50分53秒 0 - 46 1.85 1.85 |__kswapd0 12时50分53秒 0 376 - 4.63 0.00 irq/16-vmwgfx 12时50分53秒 0 - 376 4.63 0.00 |__irq/16-vmwgfx 12时50分53秒 0 490 - 19.44 0.00 xfsaild/dm-0 12时50分53秒 0 - 490 19.44 0.00 |__xfsaild/dm-0 12时50分53秒 0 794 - 10.19 0.00 vmtoolsd 12时50分53秒 0 - 794 10.19 0.00 |__vmtoolsd 12时50分53秒 0 - 815 0.93 0.00 |__HangDetector 12时50分53秒 0 - 1389 0.93 0.00 |__tuned 12时50分53秒 0 - 1244 0.93 0.00 |__in:imjournal 12时50分53秒 10000 1307 - 0.93 0.00 dmserver 12时50分53秒 10000 - 1307 0.93 0.00 |__dmserver 12时50分53秒 10000 - 1404 68.52 5.56 |__dm_io_thd 12时50分53秒 10000 - 1405 66.67 16.67 |__dm_io_thd 12时50分53秒 10000 - 1406 66.67 19.44 |__dm_io_thd 12时50分53秒 10000 - 1407 61.11 9.26 |__dm_io_thd 12时50分53秒 10000 - 1408 63.89 7.41 |__dm_io_thd 12时50分53秒 10000 - 1409 71.30 10.19 |__dm_io_thd 12时50分53秒 10000 - 1410 64.81 20.37 |__dm_io_thd 12时50分53秒 10000 - 1411 72.22 20.37 |__dm_io_thd 12时50分53秒 10000 - 1412 69.44 10.19 |__dm_io_thd 12时50分53秒 10000 - 1413 65.74 9.26 |__dm_io_thd 12时50分53秒 10000 - 1414 71.30 5.56 |__dm_io_thd 12时50分53秒 10000 - 1415 69.44 34.26 |__dm_io_thd 12时50分53秒 10000 - 1416 69.44 7.41 |__dm_io_thd 12时50分53秒 10000 - 1417 69.44 7.41 |__dm_io_thd 12时50分53秒 10000 - 1418 67.59 25.00 |__dm_io_thd 12时50分53秒 10000 - 1419 69.44 14.81 |__dm_io_thd 12时50分53秒 10000 - 1437 9.26 3.70 |__dmserver 12时50分53秒 10000 - 1443 6.48 76.85 |__dm_chkpnt_thd 12时50分53秒 10000 - 1444 1739.81 463.89 |__dm_redolog_thd 12时50分53秒 10000 - 1509 0.93 0.00 |__dm_tskwrk_thd 12时50分53秒 10000 - 1513 0.93 0.00 |__dm_tskwrk_thd 12时50分53秒 10000 - 1515 272.22 212.96 |__dm_purge_thd 12时50分53秒 10000 - 1516 0.93 0.00 |__dmserver 12时50分53秒 10000 - 1518 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1519 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1520 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1521 0.93 0.93 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1522 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1523 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1524 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1525 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1526 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1527 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1528 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1529 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1530 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1531 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1532 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1533 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1535 0.93 0.00 |__dm_sched_thd 12时50分53秒 10000 - 16742 764.81 1012.04 |__dm_sql_thd 12时50分53秒 10000 - 16743 845.37 1032.41 |__dm_sql_thd 12时50分53秒 10000 - 16744 778.70 1040.74 |__dm_sql_thd 12时50分53秒 10000 - 16745 872.22 963.89 |__dm_sql_thd 12时50分53秒 10000 - 16746 734.26 1174.07 |__dm_sql_thd 12时50分53秒 10000 - 16747 827.78 1156.48 |__dm_sql_thd 12时50分53秒 10000 - 16748 769.44 1089.81 |__dm_sql_thd 12时50分53秒 10000 - 16749 869.44 1404.63 |__dm_sql_thd 12时50分53秒 10000 - 16750 814.81 852.78 |__dm_sql_thd 12时50分53秒 10000 - 16751 763.89 1487.04 |__dm_sql_thd 12时50分53秒 10000 - 1438 0.93 0.00 |__dmserver 12时50分53秒 10000 - 1452 0.93 0.00 |__dm_redolog_thd 12时50分53秒 10000 - 1464 0.93 0.00 |__dm_tskwrk_thd 12时50分53秒 10000 - 1465 0.93 0.00 |__dm_tskwrk_thd 12时50分53秒 10000 - 1469 0.93 0.00 |__dm_tskwrk_thd 12时50分53秒 10000 - 1476 1.85 0.00 |__dm_purge_thd 12时50分53秒 10000 - 1477 0.93 0.00 |__dmserver 12时50分53秒 10000 - 1479 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1480 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1481 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1482 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1483 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1484 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1485 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1486 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1487 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1488 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1489 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1490 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1491 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1492 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1493 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1494 0.93 0.00 |__dm_wrkgrp_thd 12时50分53秒 10000 - 1496 0.93 1.85 |__dm_sched_thd 12时50分53秒 10000 1325 - 0.93 0.00 dmap 12时50分53秒 10000 - 1325 0.93 0.00 |__dmap 12时50分53秒 0 1583 - 1.85 0.00 sshd 12时50分53秒 0 - 1583 1.85 0.00 |__sshd 12时50分53秒 0 15347 - 3.70 0.93 kworker/0:0-events 12时50分53秒 0 - 15347 3.70 0.93 |__kworker/0:0-events 12时50分53秒 0 16225 - 10.19 0.00 kworker/u256:1-events_unbound 12时50分53秒 0 - 16225 10.19 0.00 |__kworker/u256:1-events_unbound 12时50分53秒 0 16488 - 31.48 0.93 kworker/1:1-events 12时50分53秒 0 - 16488 31.48 0.93 |__kworker/1:1-events 12时50分53秒 0 - 16728 8.33 0.93 |__java 12时50分53秒 0 - 16729 8.33 0.93 |__java 12时50分53秒 0 - 16730 10.19 0.00 |__java 12时50分53秒 0 - 16737 19.44 0.00 |__java 12时50分53秒 0 - 16752 1146.30 13.89 |__java 12时50分53秒 0 - 16753 1178.70 0.00 |__java 12时50分53秒 0 - 16754 1190.74 14.81 |__java 12时50分53秒 0 - 16755 1279.63 15.74 |__java 12时50分53秒 0 - 16756 1267.59 8.33 |__java 12时50分53秒 0 - 16757 1251.85 75.00 |__java 12时50分53秒 0 - 16758 1261.11 41.67 |__java 12时50分53秒 0 - 16759 1416.67 55.56 |__java 12时50分53秒 0 - 16760 1111.11 0.00 |__java 12时50分53秒 0 - 16761 1395.37 87.04 |__java 12时50分53秒 0 16908 - 0.93 0.00 kworker/1:3-ata_sff 12时50分53秒 0 - 16908 0.93 0.00 |__kworker/1:3-ata_sff 12时50分53秒 0 16950 - 0.93 117.59 pidstat 12时50分53秒 0 - 16950 0.93 116.67 |__pidstat
然后在进一步观察/proc/interrputs 来查看具体内容，res为重调度中断，可以看出值很大，说明还是过多任务的调度问题
[root@dmsh1 tools]# cat /proc/interrupts
CPU0 CPU1
0: 4 0 IO-APIC 2-edge timer
1: 9 0 IO-APIC 1-edge i8042
8: 0 1 IO-APIC 8-edge rtc0
9: 0 0 IO-APIC 9-fasteoi acpi
12: 0 15 IO-APIC 12-edge i8042
14: 0 0 IO-APIC 14-edge ata_piix
15: 0 8329 IO-APIC 15-edge ata_piix
16: 34454 13113 IO-APIC 16-fasteoi vmwgfx, ens34
17: 12677 4034584 IO-APIC 17-fasteoi ioc0, snd_ens1371
18: 63 0 IO-APIC 18-fasteoi ehci_hcd:usb1, uhci_hcd:usb2
19: 128092 175 IO-APIC 19-fasteoi ens33, ens37
24: 0 0 PCI-MSI 344064-edge PCIe PME, pciehp
25: 0 0 PCI-MSI 346112-edge PCIe PME, pciehp
26: 0 0 PCI-MSI 348160-edge PCIe PME, pciehp
27: 0 0 PCI-MSI 350208-edge PCIe PME, pciehp
28: 0 0 PCI-MSI 352256-edge PCIe PME, pciehp
29: 0 0 PCI-MSI 354304-edge PCIe PME, pciehp
30: 0 0 PCI-MSI 356352-edge PCIe PME, pciehp
31: 0 0 PCI-MSI 358400-edge PCIe PME, pciehp
32: 0 0 PCI-MSI 360448-edge PCIe PME, pciehp
33: 0 0 PCI-MSI 362496-edge PCIe PME, pciehp
34: 0 0 PCI-MSI 364544-edge PCIe PME, pciehp
35: 0 0 PCI-MSI 366592-edge PCIe PME, pciehp
36: 0 0 PCI-MSI 368640-edge PCIe PME, pciehp
37: 0 0 PCI-MSI 370688-edge PCIe PME, pciehp
38: 0 0 PCI-MSI 372736-edge PCIe PME, pciehp
39: 0 0 PCI-MSI 374784-edge PCIe PME, pciehp
40: 0 0 PCI-MSI 376832-edge PCIe PME, pciehp
41: 0 0 PCI-MSI 378880-edge PCIe PME, pciehp
42: 0 0 PCI-MSI 380928-edge PCIe PME, pciehp
43: 0 0 PCI-MSI 382976-edge PCIe PME, pciehp
44: 0 0 PCI-MSI 385024-edge PCIe PME, pciehp
45: 0 0 PCI-MSI 387072-edge PCIe PME, pciehp
46: 0 0 PCI-MSI 389120-edge PCIe PME, pciehp
47: 0 0 PCI-MSI 391168-edge PCIe PME, pciehp
48: 0 0 PCI-MSI 393216-edge PCIe PME, pciehp
49: 0 0 PCI-MSI 395264-edge PCIe PME, pciehp
50: 0 0 PCI-MSI 397312-edge PCIe PME, pciehp
51: 0 0 PCI-MSI 399360-edge PCIe PME, pciehp
52: 0 0 PCI-MSI 401408-edge PCIe PME, pciehp
53: 0 0 PCI-MSI 403456-edge PCIe PME, pciehp
54: 0 0 PCI-MSI 405504-edge PCIe PME, pciehp
55: 0 0 PCI-MSI 407552-edge PCIe PME, pciehp
56: 1244 0 PCI-MSI 129024-edge vmw_vmci
57: 0 0 PCI-MSI 129025-edge vmw_vmci
NMI: 0 0 Non-maskable interrupts
LOC: 3924413 4258052 Local timer interrupts
SPU: 0 0 Spurious interrupts
PMI: 0 0 Performance monitoring interrupts
IWI: 917 1641 IRQ work interrupts
RTR: 0 0 APIC ICR read retries
RES: 3961986 8852831 Rescheduling interrupts
CAL: 78741 78971 Function call interrupts
TLB: 20224 18382 TLB shootdowns
TRM: 0 0 Thermal event interrupts
THR: 0 0 Threshold APIC interrupts
DFR: 0 0 Deferred Error APIC interrupts
MCE: 0 0 Machine check exceptions
MCP: 26 27 Machine check polls
ERR: 0
MIS: 0
PIN: 0 0 Posted-interrupt notification event
NPI: 0 0 Nested posted-interrupt event
PIW: 0 0 Posted-interrupt wakeup event
随后我猜测可能是io导致的sys升高，随后我先去看了下dm数据库的写系统调用情况,这边使用到了strace命令去查看
发现，有大量的写请求，并且我也去查了下read，发现read也非常多，大多其中在文件描述符47-56左右，那么我们去看下这些文件描述符都是什么东西
[root@dmsh1 tools]# ps -ef | grep dmserver dmdba 1307 1 36 10:39 ? 00:53:38 /dm8/bin/dmserver path=/dm8/data/DAMENG/dm.ini -noconsole dmdba 1316 1 0 10:39 ? 00:00:07 /opt/dmdbms/bin/dmserver path=/opt/dmdbms/data/DAMENG/dm.ini -noconsole mount root 17744 12787 0 13:05 pts/1 00:00:00 grep --color=auto dmserver [root@dmsh1 tools]# strace -p 1307 -f 2>&1 | grep write 搜索该进程的写系统调用 [pid 1444] <... pwrite64 resumed> ) = 4608 [pid 17584] write(50, "10 273 F 365240 1 "..., 134[pid 17584] <... write resumed> ) = 134 [pid 17582] write(48, "37 273 244237 n "..., 64) = 64 [pid 17582] write(48, "36 273 26 263240 1 "..., 86 [pid 17584] write(50, "7 273 \1 341240 1 "..., 412 [pid 17582] <... write resumed> ) = 86 [pid 17586] write(52, "t 273 t 306237 16 "..., 180) = 180 [pid 17584] <... write resumed> ) = 412 [pid 17590] write(56, " 30 30 "..., 88 [pid 17590] <... write resumed> ) = 88 [pid 17584] write(50, "10 273 M 376240 1 "..., 141 [pid 1444] pwrite64(7, " n |10 337233W2323220JM1 bM20 bM"..., 2560, 154957824 [pid 17584] <... write resumed> ) = 141 [pid 1444] <... pwrite64 resumed> ) = 2560 [pid 17589] write(55, "7 273 X1 345240 1 "..., 408 [pid 17589] <... write resumed> ) = 408 [pid 17586] write(52, "n 273 t 305235 16 "..., 180 [pid 17586] <... write resumed> ) = 180 [pid 17581] write(47, "7 273 Q1 354240 1 "..., 401 [pid 17583] write(49, "7 273 R1 357240 1 "..., 402 [pid 17585] write(51, "16 273 314 y240 1 "..., 268 [pid 17583] <... write resumed> ) = 402 [pid 17585] <... write resumed> ) = 268 [pid 17588] write(54, " 30 30 "..., 88 [pid 17587] write(53, "7 273 N1 363240 1 "..., 398 [pid 17588] <... write resumed> ) = 88 [pid 17587] <... write resumed> ) = 398 [pid 17581] <... write resumed> ) = 401 [pid 1444] pwrite64(7, " 20 (17 337233W2323220JM1 cM20 cM"..., 4096, 154960384 [pid 17583] write(49, "10 273 Z 351240 1 "..., 154 [pid 1444] <... pwrite64 resumed> ) = 4096 [pid 17581] write(47, "10 273 M 376240 1 "..., 141 [pid 17589] write(55, "10 273 c 320240 1 "..., 163 [pid 17589] <... write resumed> ) = 163 [pid 17581] <... write resumed> ) = 141 [pid 17583] <... write resumed> ) = 154 [pid 17588] write(54, "21 273 252237 1 "..., 64 [pid 17586] write(52, " 30 30 "..., 88) = 88 [pid 17585] write(51, "22 273 251237 1 "..., 64 [pid 17586] write(52, "21 273 252237 1 "..., 64 [pid 17586] <... write resumed> ) = 64 [pid 17588] <... write resumed> ) = 64 [pid 17586] write(52, "f 273 ` 327240 1 "..., 160 [pid 17586] <... write resumed> ) = 160 [pid 17585] <... write resumed> ) = 64 [pid 17589] write(55, "7 273 b1 337240 1 "..., 418 [pid 17588] write(54, "f 273 l 333240 1 "..., 172 [pid 17582] write(48, " 273 233237 1 "..., 64 [pid 17582] <... write resumed> ) = 64 [pid 17589] <... write resumed> ) = 418 [pid 17584] write(50, "7 273 Y1 344240 1 "..., 409 [pid 17585] write(51, "24 273 257235 1 "..., 64 [pid 17582] write(48, "32 273 107 256240 377377377377377377377177"..., 1864) = 1864 [pid 17581] write(47, "7 273 [1 346240 1 "..., 411 [pid 17582] write(48, "33 273 240236 1 "..., 64 [pid 17581] <... write resumed> ) = 411 [pid 17582] <... write resumed> ) = 64 [pid 17581] write(47, "10 273 S 340240 1 "..., 147 [pid 17582] write(48, "35 273 246237 1 "..., 64 [pid 17581] <... write resumed> ) = 147 [pid 17582] <... write resumed> ) = 64 [pid 17581] write(47, "7 273 c1 336240 1 "..., 419 [pid 17582] write(48, "34 273 22 265240 1 "..., 82 [pid 17581] <... write resumed> ) = 419 [pid 17582] <... write resumed> ) = 82 [pid 17582] write(48, "37 273 244237 v "..., 64 [pid 17581] write(47, "10 273 ` 323240 1 "..., 160) = 160 [pid 17582] <... write resumed> ) = 64 [pid 17581] write(47, "7 273 [1 346240 1 "..., 411 [pid 17586] write(52, "20 273 253237 1 "..., 64 [pid 17581] <... write resumed> ) = 411 [pid 17588] <... write resumed> ) = 172 [pid 17587] write(53, "t 273 < 216237 7 "..., 124 [pid 17584] <... write resumed> ) = 409 [pid 17581] write(47, "10 273 X 353240 1 "..., 152 [pid 17582] write(48, "36 273 26 263240 1 "..., 86 [pid 17582] <... write resumed> ) = 86 [pid 17581] <... write resumed> ) = 152 [pid 17585] <... write resumed> ) = 64 [pid 17581] write(47, "7 273 ^1 343240 1 "..., 414 [pid 17583] write(49, "7 273 _1 342240 1 "..., 415 [pid 17589] write(55, "10 273 R 341240 1 "..., 146 [pid 17582] write(48, " 273 233237 1 "..., 64 [pid 17581] <... write resumed> ) = 414 [pid 17582] <... write resumed> ) = 64 [pid 17581] write(47, "10 273 Y 352240 1 "..., 153 [pid 17589] <... write resumed> ) = 146 [pid 1444] pwrite64(7, " 26 37524 337233W2323220JM1 dM20 dM"..., 5632, 154964480 [pid 17581] <... write resumed> ) = 153 [pid 17582] write(48, "32 273 107 256240 377377377377377377377177"..., 1864 [pid 17581] write(47, "7 273 X1 345240 1 "..., 408 [pid 17582] <... write resumed> ) = 1864 [pid 1444] <... pwrite64 resumed> ) = 5632 [pid 17581] <... write resumed> ) = 408 [pid 17581] write(47, "10 273 ^ 355240 1 "..., 158 [pid 17588] write(54, "20 273 253237 1 "..., 64 [pid 17583] <... write resumed> ) = 415 [pid 17590] write(56, "31 273 26 264240 1 "..., 86 [pid 17586] <... write resumed> ) = 64 [pid 17590] <... write resumed> ) = 86 [pid 17584] write(50, "10 273 T 347240 1 "..., 148 [pid 17581] <... write resumed> ) = 158 [pid 17582] write(48, "33 273 240236 1 "..., 64) = 64 [pid 17584] <... write resumed> ) = 148 [pid 17585] write(51, " 30 30 "..., 88 [pid 17581] write(47, "7 273 T1 351240 1 "..., 404 [pid 17585] <... write resumed> ) = 88 [pid 17581] <... write resumed> ) = 404 [pid 17582] write(48, "35 273 246237 1 "..., 64 [pid 17582] <... write resumed> ) = 64 [pid 17582] write(48, "34 273 22 265240 1 "..., 82 [pid 17586] write(52, "v 273 [ 353240 1 "..., 155 [pid 17582] <... write resumed> ) = 82 [pid 17590] write(56, " 30 30 "..., 88 [pid 17588] <... write resumed> ) = 64 [pid 17587] <... write resumed> ) = 124 [pid 17586] <... write resumed> ) = 155
随后我们使用到lsof工具去分析对应文件描述符的内容,可以看到对应文件描述符都是连接，而且这边看到最下面有10个 TCP dmsh1:5560->dmsh1:39140 (ESTABLISHED)这种的连接一直在进行读写操作，并且benchmarksql.dbf数据文件占用非常大
[root@dmsh1 tools]# lsof -p 1307 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME dmserver 1307 dmdba cwd DIR 253,0 8192 115842637 /dm8/bin dmserver 1307 dmdba rtd DIR 253,0 255 64 / dmserver 1307 dmdba txt REG 253,0 66314685 115865451 /dm8/bin/dmserver dmserver 1307 dmdba mem REG 253,0 180624 67160615 /usr/lib64/gconv/GB18030.so dmserver 1307 dmdba mem REG 253,0 16752 67160807 /usr/lib64/gconv/UTF-16.so dmserver 1307 dmdba mem REG 253,0 11392 33585896 /usr/lib64/libfreebl3.so dmserver 1307 dmdba mem REG 253,0 402384 33586267 /usr/lib64/libpcre.so.1.2.0 dmserver 1307 dmdba mem REG 253,0 40600 33586160 /usr/lib64/libcrypt-2.17.so dmserver 1307 dmdba mem REG 253,0 155744 33586216 /usr/lib64/libselinux.so.1 dmserver 1307 dmdba mem REG 253,0 121312 33555077 /usr/lib64/libsasl2.so.3.0.0 dmserver 1307 dmdba mem REG 253,0 109976 33586189 /usr/lib64/libresolv-2.17.so dmserver 1307 dmdba mem REG 253,0 15688 33613291 /usr/lib64/libkeyutils.so.1.5 dmserver 1307 dmdba mem REG 253,0 67104 33555073 /usr/lib64/libkrb5support.so.0.1 dmserver 1307 dmdba mem REG 253,0 2520920 33590339 /usr/lib64/libcrypto.so.1.0.2k dmserver 1307 dmdba mem REG 253,0 470328 33613611 /usr/lib64/libssl.so.1.0.2k dmserver 1307 dmdba mem REG 253,0 90160 33586221 /usr/lib64/libz.so.1.2.7 dmserver 1307 dmdba mem REG 253,0 352496 33555218 /usr/lib64/libldap-2.4.so.2.10.7 dmserver 1307 dmdba mem REG 253,0 61880 33555216 /usr/lib64/liblber-2.4.so.2.10.7 dmserver 1307 dmdba mem REG 253,0 15856 33586224 /usr/lib64/libcom_err.so.2.1 dmserver 1307 dmdba mem REG 253,0 210784 33613654 /usr/lib64/libk5crypto.so.3.1 dmserver 1307 dmdba mem REG 253,0 967840 33613660 /usr/lib64/libkrb5.so.3.3 dmserver 1307 dmdba mem REG 253,0 320720 33613617 /usr/lib64/libgssapi_krb5.so.2.2 dmserver 1307 dmdba mem REG 253,0 251784 33554509 /usr/lib64/libnspr4.so dmserver 1307 dmdba mem REG 253,0 20040 33586207 /usr/lib64/libplc4.so dmserver 1307 dmdba mem REG 253,0 15752 33586212 /usr/lib64/libplds4.so dmserver 1307 dmdba mem REG 253,0 198992 33586211 /usr/lib64/libnssutil3.so dmserver 1307 dmdba mem REG 253,0 1299920 33555116 /usr/lib64/libnss3.so dmserver 1307 dmdba mem REG 253,0 168096 33555117 /usr/lib64/libsmime3.so dmserver 1307 dmdba mem REG 253,0 412984 33555118 /usr/lib64/libssl3.so dmserver 1307 dmdba mem REG 253,0 186704 33554848 /usr/lib64/libssh2.so.1.0.1 dmserver 1307 dmdba mem REG 253,0 208920 33613239 /usr/lib64/libidn.so.11.6.11 dmserver 1307 dmdba mem REG 253,0 439280 33554850 /usr/lib64/libcurl.so.4.3.0 dmserver 1307 dmdba mem REG 253,0 115816 33586166 /usr/lib64/libnsl-2.17.so dmserver 1307 dmdba mem REG 253,0 4768363 115842807 /dm8/bin/libxerces-c-3.1.so dmserver 1307 dmdba mem REG 253,0 5673306 115842809 /dm8/bin/libxqilla.so dmserver 1307 dmdba mem REG 253,0 2454131 115842802 /dm8/bin/libgeos.so dmserver 1307 dmdba mem REG 253,0 261008 115842803 /dm8/bin/libgeos_c.so dmserver 1307 dmdba mem REG 253,0 106172832 33586146 /usr/lib/locale/locale-archive dmserver 1307 dmdba mem REG 253,0 113411 115842804 /dm8/bin/libregex.so dmserver 1307 dmdba mem REG 253,0 50794 115842805 /dm8/bin/libsnappy.so dmserver 1307 dmdba mem REG 253,0 134588 115842810 /dm8/bin/libz.so dmserver 1307 dmdba mem REG 253,0 24084 18009547 /dm8/bin/external_crypto_libs/libopenssl_crypto.so dmserver 1307 dmdba mem REG 253,0 3243641 115842654 /dm8/bin/libcrypto.so dmserver 1307 dmdba mem REG 253,0 61560 33586175 /usr/lib64/libnss_files-2.17.so dmserver 1307 dmdba mem REG 253,0 88720 34348130 /usr/lib64/libgcc_s-4.8.5-20150702.so.1 dmserver 1307 dmdba mem REG 253,0 2156592 33586156 /usr/lib64/libc-2.17.so dmserver 1307 dmdba mem REG 253,0 1136944 33586164 /usr/lib64/libm-2.17.so dmserver 1307 dmdba mem REG 253,0 995840 33555095 /usr/lib64/libstdc++.so.6.0.19 dmserver 1307 dmdba mem REG 253,0 19248 33586162 /usr/lib64/libdl-2.17.so dmserver 1307 dmdba mem REG 253,0 142144 33586185 /usr/lib64/libpthread-2.17.so dmserver 1307 dmdba mem REG 253,0 43712 33586192 /usr/lib64/librt-2.17.so dmserver 1307 dmdba mem REG 253,0 163312 33586149 /usr/lib64/ld-2.17.so dmserver 1307 dmdba mem REG 253,0 26970 67160819 /usr/lib64/gconv/gconv-modules.cache dmserver 1307 dmdba 0r CHR 1,3 0t0 4 /dev/null dmserver 1307 dmdba 1w REG 253,0 301764 115775043 /dm8/log/DmServicedem.log dmserver 1307 dmdba 2w REG 253,0 301764 115775043 /dm8/log/DmServicedem.log dmserver 1307 dmdba 3u sock 0,8 0t0 25747 protocol: TCP dmserver 1307 dmdba 4u IPv6 25748 0t0 TCP *:5560 (LISTEN) dmserver 1307 dmdba 5u REG 253,0 27262976 116868514 /dm8/data/DAMENG/SYSTEM.DBF dmserver 1307 dmdba 6u REG 253,0 10485760 116868518 /dm8/data/DAMENG/TEMP.DBF dmserver 1307 dmdba 7u REG 253,0 268435456 116868512 /dm8/data/DAMENG/DAMENG01.log dmserver 1307 dmdba 8u REG 253,0 268435456 116868513 /dm8/data/DAMENG/DAMENG02.log dmserver 1307 dmdba 9u REG 253,0 439353344 116868517 /dm8/data/DAMENG/ROLL.DBF dmserver 1307 dmdba 10u REG 253,0 134217728 116868516 /dm8/data/DAMENG/MAIN.DBF dmserver 1307 dmdba 11r FIFO 0,13 0t0 25768 pipe dmserver 1307 dmdba 12w FIFO 0,13 0t0 25768 pipe dmserver 1307 dmdba 13r FIFO 0,13 0t0 25769 pipe dmserver 1307 dmdba 14w FIFO 0,13 0t0 25769 pipe dmserver 1307 dmdba 15r FIFO 0,13 0t0 25770 pipe dmserver 1307 dmdba 16w FIFO 0,13 0t0 25770 pipe dmserver 1307 dmdba 17r FIFO 0,13 0t0 25771 pipe dmserver 1307 dmdba 18w FIFO 0,13 0t0 25771 pipe dmserver 1307 dmdba 19r FIFO 0,13 0t0 25772 pipe dmserver 1307 dmdba 20w FIFO 0,13 0t0 25772 pipe dmserver 1307 dmdba 21r FIFO 0,13 0t0 25773 pipe dmserver 1307 dmdba 22w FIFO 0,13 0t0 25773 pipe dmserver 1307 dmdba 23r FIFO 0,13 0t0 25774 pipe dmserver 1307 dmdba 24w FIFO 0,13 0t0 25774 pipe dmserver 1307 dmdba 25r FIFO 0,13 0t0 25775 pipe dmserver 1307 dmdba 26w FIFO 0,13 0t0 25775 pipe dmserver 1307 dmdba 27r FIFO 0,13 0t0 25776 pipe dmserver 1307 dmdba 28w FIFO 0,13 0t0 25776 pipe dmserver 1307 dmdba 29r FIFO 0,13 0t0 25777 pipe dmserver 1307 dmdba 30w FIFO 0,13 0t0 25777 pipe dmserver 1307 dmdba 31r FIFO 0,13 0t0 25778 pipe dmserver 1307 dmdba 32w FIFO 0,13 0t0 25778 pipe dmserver 1307 dmdba 33r FIFO 0,13 0t0 25779 pipe dmserver 1307 dmdba 34w FIFO 0,13 0t0 25779 pipe dmserver 1307 dmdba 35r FIFO 0,13 0t0 25780 pipe dmserver 1307 dmdba 36w FIFO 0,13 0t0 25780 pipe dmserver 1307 dmdba 37r FIFO 0,13 0t0 25781 pipe dmserver 1307 dmdba 38w FIFO 0,13 0t0 25781 pipe dmserver 1307 dmdba 39r FIFO 0,13 0t0 25782 pipe dmserver 1307 dmdba 40w FIFO 0,13 0t0 25782 pipe dmserver 1307 dmdba 41r FIFO 0,13 0t0 25783 pipe dmserver 1307 dmdba 42w FIFO 0,13 0t0 25783 pipe dmserver 1307 dmdba 43u IPv6 79075 0t0 TCP dmsh1:5560->192.168.50.100:57599 (ESTABLISHED) dmserver 1307 dmdba 44u IPv6 79076 0t0 TCP dmsh1:5560->192.168.50.100:57600 (ESTABLISHED) dmserver 1307 dmdba 45u IPv6 103364 0t0 TCP dmsh1:5560->dmsh1:39134 (ESTABLISHED) dmserver 1307 dmdba 46u REG 253,0 3186622464 102364749 /dm8/data/DAMENG/BENCHMARKSQL1.DBF dmserver 1307 dmdba 47u IPv6 103365 0t0 TCP dmsh1:5560->dmsh1:39140 (ESTABLISHED) dmserver 1307 dmdba 48u IPv6 103367 0t0 TCP dmsh1:5560->dmsh1:39144 (ESTABLISHED) dmserver 1307 dmdba 49u IPv6 103368 0t0 TCP dmsh1:5560->dmsh1:39148 (ESTABLISHED) dmserver 1307 dmdba 50u IPv6 103369 0t0 TCP dmsh1:5560->dmsh1:39152 (ESTABLISHED) dmserver 1307 dmdba 51u IPv6 103370 0t0 TCP dmsh1:5560->dmsh1:39162 (ESTABLISHED) dmserver 1307 dmdba 52u IPv6 103371 0t0 TCP dmsh1:5560->dmsh1:39178 (ESTABLISHED) dmserver 1307 dmdba 53u IPv6 103372 0t0 TCP dmsh1:5560->dmsh1:39180 (ESTABLISHED) dmserver 1307 dmdba 54u IPv6 103373 0t0 TCP dmsh1:5560->dmsh1:39194 (ESTABLISHED) dmserver 1307 dmdba 55u IPv6 103375 0t0 TCP dmsh1:5560->dmsh1:39208 (ESTABLISHED) dmserver 1307 dmdba 56u IPv6 103377 0t0 TCP dmsh1:5560->dmsh1:39222 (ESTABLISHED)
然后我们使用filetop工具去查看下，他可以跟踪内核文件的读写情况（使用该工具需要安装bcc）
发现有大量的读在读取benchmark.dbf数据文件，并且还伴有写入操作
[root@dmsh1 tools]# ./filetop -C Tracing... Output every 1 secs. Hit Ctrl-C to end 13:10:47 loadavg: 13.55 9.98 7.25 11/351 17997 TID COMM READS WRITES R_Kb W_Kb T FILE 1444 dm_redolog_thd 0 554 0 3038 R DAMENG01.log 1410 dm_io_thd 46 0 368 0 R BENCHMARKSQL1.DBF 1404 dm_io_thd 43 1 344 8 R BENCHMARKSQL1.DBF 1405 dm_io_thd 42 1 336 8 R BENCHMARKSQL1.DBF 1415 dm_io_thd 42 1 336 8 R BENCHMARKSQL1.DBF 1419 dm_io_thd 41 1 328 8 R BENCHMARKSQL1.DBF 1414 dm_io_thd 42 0 336 0 R BENCHMARKSQL1.DBF 1413 dm_io_thd 40 1 320 8 R BENCHMARKSQL1.DBF 1406 dm_io_thd 40 1 320 8 R BENCHMARKSQL1.DBF 1407 dm_io_thd 39 1 312 8 R BENCHMARKSQL1.DBF 1409 dm_io_thd 39 1 312 8 R BENCHMARKSQL1.DBF 1408 dm_io_thd 38 0 304 0 R BENCHMARKSQL1.DBF 1416 dm_io_thd 37 1 296 8 R BENCHMARKSQL1.DBF 1411 dm_io_thd 37 1 296 8 R BENCHMARKSQL1.DBF 1418 dm_io_thd 37 0 296 0 R BENCHMARKSQL1.DBF 1417 dm_io_thd 35 1 280 8 R BENCHMARKSQL1.DBF 1412 dm_io_thd 36 0 288 0 R BENCHMARKSQL1.DBF 1413 dm_io_thd 21 1 168 8 R ROLL.DBF 1411 dm_io_thd 21 1 168 8 R ROLL.DBF 1408 dm_io_thd 21 1 168 8 R ROLL.DBF总结
通过上述排查，可以推断，目前是因为某个脚本或者程序通过dm的sql线程去频繁读取和插入benchmarksql1.dbf文件，并且在期间产生了10个连接去频繁操作这些内容，由于频繁的执行读跟写，导致资源不足或者强行调度，出现了大量上下文切换，从而引发了sys升高问题，通过排查数据文件，以及查看库中的表发现是当前tpcc压测导致的系统升高问题，tpcc测试频繁像benchmark数据文件进行插入跟读取导致
当然，此次分析仅仅是作为新手尝试分析，后续自己也会多多加强这方面的学习！
如果你还有其他问题，欢迎到达梦社区来提问~
社区地址：https://eco.dameng.com
