Unexpected i/o error from fdb-c-apis

ZhangHuiGui · August 8, 2022, 9:30am

We use the fdb-c-apis and the single fdbserver is runing on a kubernates-pod.
Our fdb-c-apis demo is running on another pod in a same docker container with fdbserver’s pod.

Problem is we find an I/O error with : fdb error 1510 - Disk i/o operation failed. But we didn’t find any
io_error log information in the fdbserver’s log (trace xml files) and the os dmesg log (our disk and filesystem is local physical machine), and the problem can be reproduced by execute fdbcli --exec "status minimal"

There are to questions

Do all of io_error will record in fdbserver’s log files? For our environment , io_error didn’t record in server’s logs.
Are there any options to open fdbclient’s log ? Or does fdbclient report io_error by itself rather than get error from fdbserver?

Below is my server’s severity >=30 's record, but have no io_error:

<Event Severity="30" Time="1659955317.624862" DateTime="2022-08-08T10:41:57Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="66" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955322.734909" DateTime="2022-08-08T10:42:02Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="72" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955327.734999" DateTime="2022-08-08T10:42:07Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="87" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955332.767640" DateTime="2022-08-08T10:42:12Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="100" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955337.808532" DateTime="2022-08-08T10:42:17Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="94" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955342.810551" DateTime="2022-08-08T10:42:22Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="94" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955347.810572" DateTime="2022-08-08T10:42:27Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="102" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955352.813167" DateTime="2022-08-08T10:42:32Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="101" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955357.831395" DateTime="2022-08-08T10:42:37Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="99" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955361.815235" DateTime="2022-08-08T10:42:41Z" Type="RatekeeperGetSSListLongLatency" ID="7f6b8ee67cad2665" Latency="9.56104" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955362.831416" DateTime="2022-08-08T10:42:42Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="92" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955367.924809" DateTime="2022-08-08T10:42:47Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="27" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955372.924938" DateTime="2022-08-08T10:42:52Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="71" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955377.945565" DateTime="2022-08-08T10:42:57Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="105" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955382.945697" DateTime="2022-08-08T10:43:02Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="108" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955388.037698" DateTime="2022-08-08T10:43:08Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="108" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955393.051988" DateTime="2022-08-08T10:43:13Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="107" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955398.104285" DateTime="2022-08-08T10:43:18Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="106" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955403.104336" DateTime="2022-08-08T10:43:23Z" Type="TraceEventThrottle_TransactionMetrics" ID="0000000000000000" SuppressedEventCount="106" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
trace.10.244.9.88.4500.1659952548.JDcmqO.0.7.xml
<Event Severity="30" Time="1659955440.036059" DateTime="2022-08-08T10:44:00Z" Type="SlowTask" ID="0000000000000000" TaskID="20000" MClocks="510.767" Duration="0.134662" SampleRate="1" NumYields="1" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955531.006662" DateTime="2022-08-08T10:45:31Z" Type="LargePacketReceived" ID="0000000000000000" SuppressedEventCount="0" FromPeer="10.244.9.88:34716" Length="2518616" Token="5512cfc0c8ffe2c7" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955531.006662" DateTime="2022-08-08T10:45:31Z" Type="LargeTransaction" ID="0000000000000000" SuppressedEventCount="0" Size="4741390" Client="10.244.9.88:34716" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
<Event Severity="30" Time="1659955551.006047" DateTime="2022-08-08T10:45:51Z" Type="SlowTask" ID="0000000000000000" TaskID="20000" MClocks="1715.81" Duration="0.452373" SampleRate="1" NumYields="0" ThreadID="14589711157762670654" Machine="10.244.9.88:4500" LogGroup="default" Roles="CC,CD,CP,DD,GP,MS,RK,RV,SS,TL" />
trace.10.244.9.88.4500.1659952548.JDcmqO.0.8.xml

Thanks for some suggestion!

ZhangHuiGui · August 10, 2022, 8:32am

Our fdb cluster in kubernete’s pod report io_error is come from AsyncFileCached.actor.cpp:

Future<Void> AsyncFileCached::readZeroCopy(void** data, int* length, int64_t offset) {
	++countFileCacheReads;
	++countCacheReads;

	// Only aligned page reads are zero-copy
	if (*length != pageCache->pageSize || (offset & (pageCache->pageSize - 1)) || offset + *length > this->length)
	     return io_error(); // There is no trace event, we add a trace event from here.
          ....

fdb-version : 7.1.9

So what kind of foundationdb problem i have met , for this io-error, i don’t understand.

Anyone have some suggestion about it ?