I have written a simple KV database in golang, this database runs smoothly most time, however, it hangs for a few seconds occasionally.
The version of golang and linux is:
- go version: 1.12.5
- linux version: CentOS release 6.7 (Final) 2.6.32-573.el6.x86_64
I've tried some ways to debug this problem:
- Import http/pprof package and gops package, however, I fail to get process heap stack because the process is totally unresponsive when it hangs.
- Strace tool is used to get process syscalls:
process 32573 attached with 178 threads
[pid 172460] 11:12:25.260132 futex(0xc1dc4d0f48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 24633] 11:12:25.260197 futex(0xc0dc3012c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 34073] 11:12:25.260209 futex(0xc33b8464c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 34071] 11:12:25.260233 futex(0xc3b259c148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 34069] 11:12:25.260264 futex(0xc1f7eef648, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33989] 11:12:25.260275 futex(0xc368336f48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33988] 11:12:25.260285 futex(0xc36795cbc8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33987] 11:12:25.260293 futex(0xc368336bc8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33986] 11:12:25.260313 futex(0xc36795c848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33984] 11:12:25.260320 futex(0xc36795c4c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33983] 11:12:25.260342 futex(0xc3683364c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33982] 11:12:25.260350 futex(0xc36795c148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33980] 11:12:25.260360 futex(0xc0b79d1d48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33978] 11:12:25.260368 futex(0xc0b79d19c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33977] 11:12:25.260376 futex(0xc3720559c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33974] 11:12:25.260385 futex(0xc0b79d1648, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33973] 11:12:25.260393 futex(0xc3720552c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 33972] 11:12:25.260402 futex(0xc4959e4bc8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32787] 11:12:25.260411 futex(0xc000a44f48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32786] 11:12:25.260421 futex(0xc0d5df4848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32785] 11:12:25.260431 futex(0xc0d5e5e4c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32784] 11:12:25.260440 futex(0xc0d60184c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32782] 11:12:25.260448 futex(0xc0a0eea4c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32781] 11:12:25.260456 futex(0xc0d5c2c848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32779] 11:12:25.260465 futex(0xc00068ebc8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32777] 11:12:25.260473 futex(0xc0d5df44c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32776] 11:12:25.260482 futex(0xc0005d3648, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32775] 11:12:25.260491 futex(0xc000a059c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32774] 11:12:25.260500 futex(0xc000a772c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32773] 11:12:25.260508 futex(0xc0d5ed64c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32772] 11:12:25.260518 futex(0xc0d5df24c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32770] 11:12:25.260526 futex(0xc0d5d524c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32767] 11:12:25.260534 futex(0xc0a6c66148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32766] 11:12:25.260542 futex(0xc0d5d4e4c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32763] 11:12:25.260552 futex(0x1cdada0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32761] 11:12:25.260561 futex(0xc000b54848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32760] 11:12:25.260569 futex(0xc000b60848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32756] 11:12:25.260578 futex(0xc0005d32c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32755] 11:12:25.260586 futex(0xc000a05648, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32754] 11:12:25.260594 futex(0xc0d5ed6148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32753] 11:12:25.260603 futex(0xc000185648, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32752] 11:12:25.260611 futex(0xc000a76f48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32751] 11:12:25.260620 futex(0xc08a27c148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32750] 11:12:25.260629 futex(0xc0d5e5e148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32748] 11:12:25.260643 futex(0xc075230148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32747] 11:12:25.260652 futex(0xc0d5df4148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32746] 11:12:25.260659 futex(0xc075038148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32745] 11:12:25.260667 futex(0xc0d5df2148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32744] 11:12:25.260675 futex(0xc0004a12c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32743] 11:12:25.260683 futex(0xc073c7e148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32742] 11:12:25.260692 futex(0xc0d5d52148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32741] 11:12:25.260702 futex(0xc0d5d50148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32740] 11:12:25.260711 futex(0xc0d5d4e148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32739] 11:12:25.260718 futex(0xc0d5c2c148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32738] 11:12:25.260726 futex(0xc0d5c2a148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32737] 11:12:25.260734 futex(0xc000a44848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32736] 11:12:25.260742 futex(0xc000b564c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32735] 11:12:25.260750 futex(0xc000b544c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32734] 11:12:25.260758 futex(0xc000b604c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32733] 11:12:25.260766 futex(0xc000b1c4c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32732] 11:12:25.260775 futex(0xc0001a4f48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32728] 11:12:25.260784 futex(0xc0001852c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32727] 11:12:25.260794 restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid 32725] 11:12:25.260806 futex(0xc00068e4c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32724] 11:12:25.260815 futex(0xc000aa9648, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32723] 11:12:25.260823 futex(0xc000aa92c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32722] 11:12:25.260833 futex(0xc00083abc8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32721] 11:12:25.260842 futex(0xc000868848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32718] 11:12:25.260851 futex(0xc000a76bc8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32651] 11:12:25.260859 futex(0xc000aa8bc8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32650] 11:12:25.260867 futex(0xc000aa8848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32649] 11:12:25.260875 futex(0xc0008eb648, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32648] 11:12:25.260883 futex(0xc00097dd48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32647] 11:12:25.260891 futex(0xc00097d9c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32646] 11:12:25.260899 futex(0xc00097d648, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32644] 11:12:25.260908 futex(0xc0009e1d48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32643] 11:12:25.260918 futex(0xc0008eaf48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32642] 11:12:25.260926 futex(0xc0008eabc8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32639] 11:12:25.260935 futex(0xc00097d2c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32638] 11:12:25.260945 futex(0xc00097cf48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32637] 11:12:25.260954 futex(0xc0009e1648, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32635] 11:12:25.260963 futex(0xc0008ea4c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32634] 11:12:25.260971 futex(0xc00097c848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32633] 11:12:25.260979 futex(0xc0009a6848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32631] 11:12:25.260986 futex(0xc0009e12c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32630] 11:12:25.260994 futex(0xc000aa84c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32629] 11:12:25.261002 futex(0xc000a76848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32628] 11:12:25.261009 futex(0xc000a04bc8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32627] 11:12:25.261024 futex(0xc000b60148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32626] 11:12:25.261032 futex(0xc000a04848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32625] 11:12:25.261040 futex(0xc000b54148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32624] 11:12:25.261047 futex(0xc000b56148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32623] 11:12:25.261067 futex(0xc0009e0f48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32621] 11:12:25.261076 futex(0xc0009e0bc8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32620] 11:12:25.261083 futex(0xc0009e0848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32619] 11:12:25.261101 futex(0xc00083a848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32618] 11:12:25.261110 futex(0xc0000f59c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32617] 11:12:25.261118 futex(0xc000a044c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32616] 11:12:25.261127 futex(0xc00097c4c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32613] 11:12:25.261136 futex(0xc0005d2bc8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32612] 11:12:25.261144 futex(0xc000184f48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32611] 11:12:25.261152 futex(0xc0009e04c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32610] 11:12:25.261160 futex(0xc000a444c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32609] 11:12:25.261169 futex(0xc000a764c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32608] 11:12:25.261178 futex(0xc000aa8148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32606] 11:12:25.261186 futex(0xc000a44148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32604] 11:12:25.261194 futex(0xc0009e0148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32603] 11:12:25.261207 futex(0xc0009a6148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32602] 11:12:25.261216 futex(0xc00097c148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32601] 11:12:25.261224 futex(0xc0008ea148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32600] 11:12:25.261232 futex(0xc000868148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32598] 11:12:25.261240 restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid 32596] 11:12:25.261249 futex(0xc0000c3648, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32595] 11:12:25.261257 futex(0xc0004a0848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32594] 11:12:25.261266 futex(0xc000184848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32593] 11:12:25.261276 futex(0xc0005d2848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32592] 11:12:25.261285 futex(0xc0000f5648, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32590] 11:12:25.261294 futex(0xc0001a4848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32588] 11:12:25.261302 futex(0xc0005d2148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32587] 11:12:25.261310 futex(0xc0000f4f48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32586] 11:12:25.261318 futex(0xc0001a44c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32585] 11:12:25.261325 futex(0xc000184148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32584] 11:12:25.261334 futex(0xc0004a04c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32579] 11:12:25.261343 futex(0xc0001a4148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32578] 11:12:25.261350 futex(0x1cdacb8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32577] 11:12:25.261359 futex(0xc0000f4148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32575] 11:12:25.261368 futex(0xc0000c2848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32574] 11:12:25.261377 restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid 32573] 11:12:25.261385 futex(0x1cbe8e8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32574] 11:12:25.264099 <... restart_syscall resumed> ) = 0 <0.002704>
[pid 32574] 11:12:25.264131 epoll_pwait(4<[eventpoll]>, {}, 128, 0, NULL) = 0 <0.000014>
[pid 32574] 11:12:25.264197 nanosleep({0, 10000000}, <unfinished ...>
[pid 34072] 11:12:31.236049 read(16699<socket:[371657496]>, <unfinished ...>
[pid 34070] 11:12:31.236128 read(16691<socket:[371657488]>, <unfinished ...>
[pid 33985] 11:12:31.236142 sched_yield( <unfinished ...>
[pid 33981] 11:12:31.236161 futex(0xc06ed9c148, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 33979] 11:12:31.236171 futex(0xc0d5df44c8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 33976] 11:12:31.236178 futex(0xc3720552c8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 33971] 11:12:31.236193 read(7443<socket:[371660645]>, <unfinished ...>
[pid 33975] 11:12:31.236243 futex(0xc0004a12c8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 32789] 11:12:31.236253 futex(0xc06ed9c148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32788] 11:12:31.236262 futex(0xc000a76bc8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 32783] 11:12:31.236270 read(5583<socket:[371824829]>, <unfinished ...>
[pid 32780] 11:12:31.236295 read(1258<socket:[371660662]>, <unfinished ...>
[pid 32778] 11:12:31.236311 read(2795<socket:[371660629]>, <unfinished ...>
[pid 32771] 11:12:31.236339 read(16828<socket:[371657506]>, <unfinished ...>
[pid 32769] 11:12:31.236356 read(1163<socket:[371770203]>, <unfinished ...>
[pid 32768] 11:12:31.236370 read(16955<socket:[371657515]>, <unfinished ...>
[pid 32765] 11:12:31.236385 read(16696<socket:[371657494]>, <unfinished ...>
[pid 32764] 11:12:31.236398 futex(0xc1f7eef648, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 32762] 11:12:31.236423 read(9849<socket:[371825259]>, <unfinished ...>
[pid 32759] 11:12:31.236437 read(16944<socket:[371657509]>, <unfinished ...>
[pid 32758] 11:12:31.236451 read(16684<socket:[371657485]>, <unfinished ...>
[pid 32757] 11:12:31.236473 read(3335<socket:[371657499]>, <unfinished ...>
[pid 32749] 11:12:31.236493 read(16950<socket:[371657513]>, <unfinished ...>
[pid 32731] 11:12:31.236509 futex(0xc000868148, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 32730] 11:12:31.236518 futex(0xc0008ea4c8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 32729] 11:12:31.236526 futex(0xc0000f5648, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 32726] 11:12:31.236535 futex(0xc0d5e5e4c8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 32720] 11:12:31.236544 read(6925<socket:[371811451]>, <unfinished ...>
[pid 32719] 11:12:31.236562 read(16702<socket:[371657497]>, <unfinished ...>
[pid 32717] 11:12:31.236576 read(16713<socket:[371657498]>, <unfinished ...>
[pid 32645] 11:12:31.236590 read(6490<socket:[371824831]>, <unfinished ...>
[pid 32640] 11:12:31.236608 futex(0xc0d5d4e148, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 32636] 11:12:31.236619 accept4(4105, <unfinished ...>
[pid 32632] 11:12:31.236628 read(9867<socket:[371825263]>, <unfinished ...>
[pid 32615] 11:12:31.236648 read(2699<socket:[371813455]>, <unfinished ...>
[pid 32614] 11:12:31.236665 futex(0xc00068e4c8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
GC info(from 11:00 to 11:42):
gc 4547 @519870.695s 0%: 0.64+7727+0.098 ms clock, 30+54557/86497/4449+4.7 ms cpu, 30446->36079->19800 MB, 33340 MB goal, 48 P
GC forced
gc 4548 @519998.441s 0%: 1.4+2698+0.028 ms clock, 70+71/32202/90622+1.3 ms cpu, 30366->30623->14272 MB, 39601 MB goal, 48 P
scvg3465: 921 MB released
scvg3465: inuse: 26152, idle: 73618, sys: 99771, released: 52270, consumed: 47501 (MB)
GC forced
gc 4549 @520121.156s 0%: 0.89+2614+0.029 ms clock, 42+244/31128/89017+1.3 ms cpu, 23255->23387->14064 MB, 28545 MB goal, 48 P
scvg3466: 35 MB released
scvg3466: inuse: 26928, idle: 72843, sys: 99771, released: 51276, consumed: 48494 (MB)
GC forced
gc 4550 @520243.784s 0%: 0.76+2723+0.036 ms clock, 36+184/32007/89703+1.7 ms cpu, 20919->21049->14074 MB, 28129 MB goal, 48 P
scvg3467: 17831 MB released
scvg3467: inuse: 27049, idle: 72722, sys: 99771, released: 69057, consumed: 30714 (MB)
GC forced
gc 4551 @520366.531s 0%: 0.78+2736+0.032 ms clock, 37+174/32370/91383+1.5 ms cpu, 20387->20478->14120 MB, 28149 MB goal, 48 P
scvg3468: 1808 MB released
scvg3468: inuse: 28066, idle: 71704, sys: 99771, released: 70795, consumed: 28976 (MB)
GC forced
gc 4552 @520489.286s 0%: 0.72+2641+0.034 ms clock, 34+258/31377/88676+1.6 ms cpu, 21277->21360->14002 MB, 28240 MB goal, 48 P
GC forced
gc 4553 @520611.942s 0%: 0.41+2648+0.029 ms clock, 20+58/31402/89121+1.4 ms cpu, 21806->21897->14362 MB, 28005 MB goal, 48 P
scvg3469: 34 MB released
scvg3469: inuse: 26701, idle: 73069, sys: 99771, released: 69940, consumed: 29830 (MB)
GC forced
gc 4554 @520734.608s 0%: 0.55+2685+0.038 ms clock, 26+147/32051/88317+1.8 ms cpu, 21565->21877->14352 MB, 28725 MB goal, 48 P
scvg3470: 39 MB released
scvg3470: inuse: 26641, idle: 73130, sys: 99771, released: 69576, consumed: 30195 (MB)
GC forced
gc 4555 @520857.307s 0%: 0.43+2614+0.031 ms clock, 20+0.31/31264/91012+1.5 ms cpu, 20760->20849->14183 MB, 28704 MB goal, 48 P
scvg3471: 394 MB released
scvg3471: inuse: 27167, idle: 72604, sys: 99771, released: 69929, consumed: 29841 (MB)
GC forced
gc 4556 @520979.937s 0%: 0.51+2716+0.026 ms clock, 24+116/32239/91899+1.2 ms cpu, 22069->22175->14134 MB, 28366 MB goal, 48 P
scvg3472: 720 MB released
scvg3472: inuse: 27667, idle: 72104, sys: 99771, released: 69954, consumed: 29817 (MB)
GC forced
gc 4557 @521102.679s 0%: 0.45+2737+0.051 ms clock, 21+38/32726/89390+2.4 ms cpu, 21606->21995->14750 MB, 28269 MB goal, 48 P
scvg3473: 25 MB released
scvg3473: inuse: 32397, idle: 67369, sys: 99766, released: 66966, consumed: 32800 (MB)
GC forced
gc 4558 @521225.432s 0%: 6.2+2703+0.037 ms clock, 300+104/32314/90152+1.7 ms cpu, 27118->27332->14253 MB, 29500 MB goal, 48 P
GC forced
gc 4559 @521348.157s 0%: 10+2655+0.028 ms clock, 521+447/31809/89384+1.3 ms cpu, 23382->23651->14316 MB, 28507 MB goal, 48 P
scvg3474: 51 MB released
scvg3474: inuse: 26034, idle: 73736, sys: 99771, released: 66841, consumed: 32930 (MB)
GC forced
gc 4560 @521470.837s 0%: 9.8+2605+0.026 ms clock, 474+143/30936/90046+1.2 ms cpu, 22733->22833->14100 MB, 28632 MB goal, 48 P
scvg3475: 79 MB released
scvg3475: inuse: 26480, idle: 73290, sys: 99771, released: 66906, consumed: 32864 (MB)
GC forced
gc 4561 @521593.476s 0%: 0.41+2615+0.046 ms clock, 19+159/30798/88548+2.2 ms cpu, 20629->20769->14033 MB, 28201 MB goal, 48 P
scvg3476: 2438 MB released
scvg3476: inuse: 27789, idle: 71982, sys: 99771, released: 69305, consumed: 30465 (MB)
GC forced
gc 4562 @521716.106s 0%: 0.51+2673+0.051 ms clock, 24+88/32054/92490+2.4 ms cpu, 21751->21896->14198 MB, 28066 MB goal, 48 P
scvg3477: 1294 MB released
scvg3477: inuse: 29695, idle: 70076, sys: 99771, released: 69666, consumed: 30104 (MB)
GC forced
gc 4563 @521838.810s 0%: 0.47+2635+0.028 ms clock, 22+111/31434/90845+1.3 ms cpu, 22623->22705->14057 MB, 28397 MB goal, 48 P
GC forced
gc 4564 @521961.461s 0%: 0.46+2727+0.031 ms clock, 22+155/32528/93412+1.5 ms cpu, 19763->19851->14138 MB, 28114 MB goal, 48 P
scvg3478: 142 MB released
scvg3478: inuse: 25743, idle: 74027, sys: 99771, released: 69729, consumed: 30042 (MB)
GC forced
gc 4565 @522084.205s 0%: 0.44+2657+0.029 ms clock, 21+214/31701/90716+1.4 ms cpu, 20424->20514->14179 MB, 28276 MB goal, 48 P
scvg3479: 28 MB released
scvg3479: inuse: 28391, idle: 71380, sys: 99771, released: 69228, consumed: 30543 (MB)
GC forced
gc 4566 @522206.879s 0%: 0.38+2652+0.033 ms clock, 18+108/31342/90698+1.6 ms cpu, 23690->23781->14146 MB, 28359 MB goal, 48 P
scvg3480: 557 MB released
scvg3480: inuse: 27188, idle: 72582, sys: 99771, released: 68737, consumed: 31034 (MB)
GC forced
gc 4567 @522329.545s 0%: 0.55+2585+0.031 ms clock, 26+47/30887/89360+1.5 ms cpu, 22082->22182->14378 MB, 28292 MB goal, 48 P
scvg3481: 27 MB released
scvg3481: inuse: 28056, idle: 71715, sys: 99771, released: 67790, consumed: 31981 (MB)
Vmstat info:
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
2 0 2538448 965376 985720 193366176 0 0 7468 4144 30760 37141 3 0 97 0 0
0 0 2538448 866052 985720 193425296 0 0 6096 4796 29720 36705 4 0 95 0 0
3 2 2538448 781104 985720 193466992 0 0 8868 4888 31129 40341 3 0 97 0 0
0 0 2538448 684132 985720 193525088 0 0 6456 7256 27751 34601 4 0 95 0 0
1 0 2538448 591752 985728 193568112 0 0 7588 7448 31251 39921 2 1 97 0 0
0 1 2538596 603712 985724 193519232 0 148 9192 5040 85975 41792 3 1 96 0 0
6 1 2538824 581488 985724 193478368 0 228 12044 8736 76500 44506 3 1 96 0 0
1 0 2539052 588596 985720 193401248 0 228 17488 7708 95530 47809 5 1 94 1 0
0 0 2539228 605584 985584 193341440 0 176 7720 3880 85563 38079 3 1 97 0 0
3 0 2539344 598864 985280 193296800 0 116 9784 4296 48443 41580 3 1 96 0 0
3 0 2540228 4245764 959772 189644656 0 884 7732 4464 594631 41907 3 3 94 0 0
0 0 2540588 5716636 958540 188141504 0 360 12832 35124 240269 37573 3 1 96 0 0
2 0 2540588 5614180 958540 188207216 0 0 13784 2984 27044 34481 2 0 97 0 0
0 0 2540588 5433884 958560 188269600 0 0 9644 538844 51809 47156 3 1 94 2 0
3 0 2540588 5333084 958584 188335344 0 0 15500 552292 53730 74434 2 1 93 4 0
4 0 2540588 5201944 958588 188409344 0 0 20760 5628 31898 40993 3 1 96 0 0
3 0 2540588 5110636 958588 188476512 0 0 17764 8540 29821 38110 3 1 97 0 0
0 0 2540588 4966540 958596 188550064 0 0 18972 4364 29049 35744 3 1 96 0 0
1 0 2540588 4816128 958604 188614416 0 0 14372 3448 29185 36645 3 1 97 0 0
0 0 2540588 4655996 958612 188687328 0 0 20540 16648 29179 36005 3 1 96 0 0
0 0 2540588 4476048 958620 188754208 0 0 16456 4308 29029 35896 3 1 96 0 0
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
1 0 2540588 4333448 958620 188818256 0 0 13888 13564 26797 32078 3 1 97 0 0
0 0 2540588 4117432 958620 188887184 0 0 15688 3948 29182 35576 3 1 96 0 0
6 0 2540588 3933804 958620 188948192 0 0 9872 1600 26391 31619 3 1 96 0 0
1 0 2540588 3753960 958628 189011008 0 0 11588 4104 32898 39632 3 1 96 0 0
2 0 2540588 3577940 958632 189074000 0 0 12528 4576 28383 36093 2 1 97 0 0
50 0 2540588 3457128 958648 189134080 0 0 8516 182148 67199 31207 47 1 51 1 0
49 0 2540588 3654512 958664 188890368 0 0 8172 42092 77663 13805 91 1 8 0 0
37 11 2540588 3532092 958664 188962656 0 0 23604 7932 67246 12802 92 1 6 1 0
2 0 2540588 3423520 958676 189049424 0 0 41140 36392 49538 38934 30 1 67 3 0
13 0 2540588 3353936 958676 189119248 0 0 14636 3820 31720 37868 6 1 94 0 0
1 0 2540588 3288452 958684 189185456 0 0 14984 10288 27419 29717 5 1 94 0 0
0 0 2540588 3228116 958684 189244896 0 0 8464 3180 27235 33955 2 0 97 0 0
2 0 2540588 3181408 958684 189290576 0 0 11088 2968 27061 32916 3 0 97 0 0
0 0 2540588 3115948 958692 189356912 0 0 13488 22464 30301 38231 2 0 97 0 0
1 0 2540588 3049144 958700 189423712 0 0 13900 4504 30000 37108 3 1 96 0 0
1 0 2540588 2985992 958708 189486880 0 0 12216 10648 28751 34676 2 0 97 0 0
1 0 2540588 2922520 958708 189551104 0 0 13076 3224 28077 34695 3 0 97 0 0
0 1 2540588 2863000 958708 189611968 0 0 6900 2748 27320 34072 3 0 97 0 0
1 0 2540588 2799620 958720 189674800 0 0 13164 18360 29380 36358 3 1 96 0 0
0 0 2540588 2746148 958728 189727936 0 0 12840 4884 29313 37243 2 0 97 0 0
1 0 2540588 2686116 958740 189788928 0 0 8024 33552 28742 34802 3 0 97 0 0
as the second strace info block shown, when the time was between 11:12:25.264197 and 11:12:31.236049, no syscall was invoked, but the client was still writing data to this database.
I have no ideas about what the process is doing when the process hangs.
Any suggestions to help me investigate this problem?
Is there any tools to get process stack when the process hangs?
Maybe I need the answer to this question: How can I dump all a Go process's stacks without killing it?
