Transaction timing out on 586 embedded CPU

[Kai Scharwies]

2012/12/4 Bjørn Mork <bjorn at mork.no>:
> Kai Scharwies <kai at scharwies.de> writes:
>
>> I saw the line "read(3, 0xbfdfbd6c, 16)                 = -1 EAGAIN
>> (Resource temporarily unavailable)" in strace. Could that be the
>> problem?
>
> That looks normal to me.  Just means that there were no data available
> for the non blocking read.
>
>
>> eventfd2(0, O_NONBLOCK|O_CLOEXEC)       = 3
>
> So fd 3 is the eventfd
>
>> open("/dev/cdc-wdm0", O_RDWR|O_EXCL|O_NOCTTY|O_NONBLOCK) = 4
>
> and fd 4 is the character device
>
>> write(4, "\1\17\0\0\0\0\0\1\"\0\4\0\1\1\0\2", 16) = 16
>
> writing first QMI message
>
>> poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 10625) = 1
>> ([{fd=4, revents=POLLIN}])
>
> the driver signals data ready
>
>> read(3, 0xbfdfbd6c, 16)                 = -1 EAGAIN (Resource
>
> don't understand why this is done, but it should be harmless
>
>> read(4, "\1\27\0\200\0\0\1\1\"\0\f\0\2\4\0\0\0\0\0\1\2\0\2\7", 2048) = 24
>
> successfully read the QMI message from the driver
>
>> write(4, "\1\f\0\0\2\7\0\1\0%\0\0\0", 13) = 13
>
> writing next QMI message to the driver
>
>> poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 10611) = 0 (Timeout)
>> read(3, 0xbfdfbd6c, 16)                 = -1 EAGAIN (Resource
>> temporarily unavailable)
>> clock_gettime(CLOCK_MONOTONIC, {77050, 15159036}) = 0
>> poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
>> write(2, "error: operation failed: Transac"..., 47error: operation
>> failed: Transaction timed out
>> ) = 47
>
> Then just silence from the driver until the poll times out.  Strange.
> Polling worked above, so why not here too?
>
> Unless you are doing the same I usually do whenever I play with
> NetworkManager and ModemManager: Do you have some other process running
> and reading from /dev/cdc-wdm0? lsof will tell.  It's perfectly possible
> to have multiple processes reading from the device at the same time, but
> only one of them will see each QMI message from the driver. This results
> in failures like yours when some other process has "stolen" the QMI
> message you are waiting for.
>
> I have considered ways to avoid this by driver modifications (copying
> all messages to all readers, or making open exclusive), but rejected
> them.  This is not possible without changing the userspace API and
> that's a no-no.
>
> But let's verify if this indeed is the problem first.
>
>
>
> Bjørn

Neither the patch from Aleksander, nor increasing the timeout is successful.
This is before increasing the timeout:

root at MeshUnit13:~# time qmicli -d /dev/cdc-wdm0 --dms-get-ids
error: operation failed: Transaction timed out

real	0m10.692s
user	0m0.020s
sys	0m0.020s

And this is after changing it to 25 seconds:

root at MeshUnit13:~# time qmicli -d /dev/cdc-wdm0 --dms-get-ids
error: operation failed: Transaction timed out

real	0m25.771s
user	0m0.020s
sys	0m0.020s

It doesn't seem another process is accessing /dev/cdc-acm0:

root at MeshUnit13:~/lte/libqmi-1.0.0# lsof | grep cdc
qmicli    25861             root    4u      CHR    180,176      0t0
  16228 /dev/cdc-wdm0
pool      25861 25862       root    4u      CHR    180,176      0t0
  16228 /dev/cdc-wdm0

Very strange...

Kai