Can someone please tell me how io_trust_seconds work?
Or How can we detect disk stalls in general?
I created a small cluster (1 host, 3 process) with io_trust_seconds set to 5 seconds, then stalled the disk on the storage server via fuse filesystem. I was expecting to see some kind of timeout error, but the entire process got stalled instead until the disk came back.
The following is the trace logs on the storage server when I stalled the disk after 1573579506.935685.
(It’s interesting the second line showed up after the disk came back, but the timestamp is only 3 seconds after the previous line.)
{"Severity":"10","Time":"1573579506.935685","Type":"MachineMetrics","ID":"0000000000000000","Elapsed":"5.00012","MbpsSent":"70.7843","MbpsReceived":"70.7843","OutSegs":"228751","RetransSegs":"0","CPUSeconds":"4.7144","TotalMemory":"7993544704","CommittedMemory":"1441497088","AvailableMemory":"6552047616","ZoneID":"d168b16bcd45a2081e434b59a2e60cbd","MachineID":"d168b16bcd45a2081e434b59a2e60cbd","Machine":"127.0.0.1:4501","LogGroup":"default","Roles":"SS","TrackLatestType":"Original"}
{"Severity":"30","Time":"1573579509.597792","Type":"SlowTask","ID":"0000000000000000","TaskID":"9000","MClocks":"90003","Duration":"30.0007","SampleRate":"1","NumYields":"0","Machine":"127.0.0.1:4501","LogGroup":"default","Roles":"SS"}
{"Severity":"20","Time":"1573579509.597792","Type":"Net2SlowTaskTrace","ID":"0000000000000000","TraceTime":"1573579519.598367","Trace":"addr2line -e fdbserver.debug -p -C -f -i 0x7f28d39fd5f0 0x7f28d3209467 0x7f28d32094db 0x1e9a68a 0xc12674 0x10f0b50 0x1132a64 0x79cf01 0x1d65a5e 0x1d65c95 0x1e81628 0x73da6f 0x7f28d313c505 0x776cf5","Machine":"127.0.0.1:4501","LogGroup":"default","Roles":"SS"}
{"Severity":"20","Time":"1573579509.597792","Type":"Net2SlowTaskTrace","ID":"0000000000000000","TraceTime":"1573579539.598582","Trace":"addr2line -e fdbserver.debug -p -C -f -i 0x7f28d39fd5f0 0x7f28d3209275 0x7f28d32094f7 0x1e9a68a 0xc12674 0x10f0b50 0x1132a64 0x79cf01 0x1d65a5e 0x1d65c95 0x1e81628 0x73da6f 0x7f28d313c505 0x776cf5","Machine":"127.0.0.1:4501","LogGroup":"default","Roles":"SS"}
{"Severity":"10","Time":"1573579509.597792","Type":"SomewhatSlowRunLoopBottom","ID":"0000000000000000","Elapsed":"30.001","Machine":"127.0.0.1:4501","LogGroup":"default","Roles":"SS"}
{"Severity":"10","Time":"1573579509.597792","Type":"ConnectionFrom","ID":"c200d62665d48c6a","SuppressedEventCount":"7","FromAddress":"127.0.0.1:60330","ListenAddress":"127.0.0.1:4501","Machine":"127.0.0.1:4501","LogGroup":"default","Roles":"SS"}
{"Severity":"20","Time":"1573579509.597792","Type":"N2_ReadError","ID":"c200d62665d48c6a","SuppressedEventCount":"0","Message":"2","Machine":"127.0.0.1:4501","LogGroup":"default","Roles":"SS"}
{"Severity":"10","Time":"1573579509.597792","Type":"IncomingConnectionError","ID":"c200d62665d48c6a","Error":"connection_failed","ErrorDescription":"Network connection failed","ErrorCode":"1026","SuppressedEventCount":"0","FromAddress":"127.0.0.1:60330","Machine":"127.0.0.1:4501","LogGroup":"default","Roles":"SS"}
{"Severity":"20","Time":"1573579539.598975","Type":"GetDiskStatisticsDeviceNotFound","ID":"0000000000000000","Directory":"/mnt/charybdbde","Machine":"127.0.0.1:4501","LogGroup":"default","Roles":"SS"}
{"Severity":"10","Time":"1573579539.598975","Type":"MachineLoadDetail","ID":"0000000000000000","User":"182443","Nice":"270","System":"32507","Idle":"465553","IOWait":"10231","IRQ":"0","SoftIRQ":"1245","Steal":"70","Guest":"0","Machine":"127.0.0.1:4501","LogGroup":"default","Roles":"SS"}
{"Severity":"10","Time":"1573579539.598975","Type":"ProcessMetrics","ID":"0000000000000000","Elapsed":"32.6633","CPUSeconds":"2.18722","MainThreadCPUSeconds":"2.1848","UptimeSeconds":"367.688","Memory":"725852160","ResidentMemory":"518291456","UnusedAllocatedMemory":"358433984","MbpsSent":"1.81155","MbpsReceived":"2.26044","DiskTotalBytes":"98294394880","DiskFreeBytes":"90431365120","DiskQueueDepth":"0","DiskIdleSeconds":"32.6633","DiskReads":"0","DiskWrites":"0","DiskReadsCount":"0","DiskWritesCount":"0","DiskWriteSectors":"0","DiskReadSectors":"0","FileWrites":"5","FileReads":"0","CacheReadBytes":"20480","CacheFinds":"11","CacheWritesBlocked":"0","CacheReadsBlocked":"0","CachePageReadsMerged":"0","CacheWrites":"7","CacheReads":"172121","CacheHits":"172126","CacheMisses":"0","CacheEvictions":"0","ZoneID":"d168b16bcd45a2081e434b59a2e60cbd","MachineID":"d168b16bcd45a2081e434b59a2e60cbd","AIOSubmitCount":"2","AIOCollectCount":"2","AIOSubmitLag":"2.57184e-10","AIODiskStall":"6.63153e-10","CurrentConnections":"10","ConnectionsEstablished":"0","ConnectionsClosed":"0","ConnectionErrors":"0","Machine":"127.0.0.1:4501","LogGroup":"default","Roles":"SS","TrackLatestType":"Original"}
The only evidence of the disk stall was the ProcessMetrics, but it was reported after the disk came to back normal.
"DiskIdleSeconds":"32.6633"
Is this an expected behavior?
How can we detest stalled disks earlier?