Transaction timing out on 586 embedded CPU

Kai Scharwies kai at scharwies.de
Tue Dec 4 02:52:02 PST 2012


2012/12/3 Aleksander Morgado <aleksander at lanedo.com>:
>
>>     > When trying with verbose flag it takes forever, too, but some of the
>>     > expected output can be seen (however not received on time as it
>>     > seems):
>>
>>     By default all async operations in qmicli are configured with a 10s
>>     timeout, so it really may be taking longer in your case. You can either
>>     try to update those 10s to something bigger, e.g. 30s.
>>
>>     Or better, modify qmicli to add a new `--command-timeout=N' option which
>>     would allow us to specify the default number of seconds to wait in each
>>     async operation... Patches welcome :-)
>>
>>     --
>>     Aleksander
>>
>>
>> Yes, that would easily be possible, but why do the operations take
>> longer on this board than on other ones in the first place?
>> It has USB2.0 support and a decent CPU, too.
>> I dont see big CPU usage, interrupt floods or such.
>>
>> How could we debug where the delay comes from?
>>
>
> Does it happen with every command you try? Or only with Get PIN status?
> If the latter, it may be because the SIM needs time to get initialized?
>
> The CID allocation request+response is really instant according to your
> logs, there's no delay in there. Same for the CID release.
>
> If you update the timeout value to e.g. 30s and you still get the same
> issue, then there may be a problem on how the data is read from the
> socket and how we actually poll for it. In your logs the reply to Get
> PIN Status actually arrived *just* after we sent the CID release; so
> that may not be a coincidence.
>
> --
> Aleksander

It happens with every command.
E.g.:
root at MeshUnit13:~# qmicli -d /dev/cdc-wdm0 --nas-get-system-info
error: operation failed: Transaction timed out
root at MeshUnit13:~# qmicli -d /dev/cdc-wdm0 --dms-get-capabilities
error: operation failed: Transaction timed out
root at MeshUnit13:~# qmicli -d /dev/cdc-wdm0 --dms-get-power-state
error: operation failed: Transaction timed out
root at MeshUnit13:~# qmicli -d /dev/cdc-wdm0 --dms-get-ids
error: operation failed: Transaction timed out

I saw the line "read(3, 0xbfdfbd6c, 16)                 = -1 EAGAIN
(Resource temporarily unavailable)" in strace. Could that be the
problem?
Here is the complete output:

root at MeshUnit13:~# strace qmicli -d /dev/cdc-wdm0 --dms-get-ids
execve("/usr/bin/qmicli", ["qmicli", "-d", "/dev/cdc-wdm0",
"--dms-get-ids"], [/* 69 vars */]) = 0
brk(0)                                  = 0x8200000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb770f000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=33841, ...}) = 0
mmap2(NULL, 33841, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7706000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/i386-linux-gnu/libgio-2.0.so.0", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\200l\2\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=1434480, ...}) = 0
mmap2(NULL, 1440236, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE,
3, 0) = 0xb75a6000
mprotect(0xb7701000, 4096, PROT_NONE)   = 0
mmap2(0xb7702000, 12288, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15b) = 0xb7702000
mmap2(0xb7705000, 2540, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7705000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/i386-linux-gnu/libgobject-2.0.so.0", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\360\233\0\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=333720, ...}) = 0
mmap2(NULL, 333792, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0xb7554000
mmap2(0xb75a4000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x50) = 0xb75a4000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libglib-2.0.so.0", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\340w\1\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=1031056, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb7553000
mmap2(NULL, 1035320, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE,
3, 0) = 0xb7456000
mmap2(0xb7551000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xfa) = 0xb7551000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/tls/i586/libqmi-glib.so.0", O_RDONLY) = -1
ENOENT (No such file or directory)
stat64("/lib/i386-linux-gnu/tls/i586", 0xbfdfb88c) = -1 ENOENT (No
such file or directory)
open("/lib/i386-linux-gnu/tls/libqmi-glib.so.0", O_RDONLY) = -1 ENOENT
(No such file or directory)
stat64("/lib/i386-linux-gnu/tls", 0xbfdfb88c) = -1 ENOENT (No such
file or directory)
open("/lib/i386-linux-gnu/i586/libqmi-glib.so.0", O_RDONLY) = -1
ENOENT (No such file or directory)
stat64("/lib/i386-linux-gnu/i586", 0xbfdfb88c) = -1 ENOENT (No such
file or directory)
open("/lib/i386-linux-gnu/libqmi-glib.so.0", O_RDONLY) = -1 ENOENT (No
such file or directory)
stat64("/lib/i386-linux-gnu", {st_mode=S_IFDIR|0755, st_size=12288, ...}) = 0
open("/usr/lib/i386-linux-gnu/tls/i586/libqmi-glib.so.0", O_RDONLY) =
-1 ENOENT (No such file or directory)
stat64("/usr/lib/i386-linux-gnu/tls/i586", 0xbfdfb88c) = -1 ENOENT (No
such file or directory)
open("/usr/lib/i386-linux-gnu/tls/libqmi-glib.so.0", O_RDONLY) = -1
ENOENT (No such file or directory)
stat64("/usr/lib/i386-linux-gnu/tls", 0xbfdfb88c) = -1 ENOENT (No such
file or directory)
open("/usr/lib/i386-linux-gnu/i586/libqmi-glib.so.0", O_RDONLY) = -1
ENOENT (No such file or directory)
stat64("/usr/lib/i386-linux-gnu/i586", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
open("/usr/lib/i386-linux-gnu/libqmi-glib.so.0", O_RDONLY) = -1 ENOENT
(No such file or directory)
stat64("/usr/lib/i386-linux-gnu", {st_mode=S_IFDIR|0755,
st_size=16384, ...}) = 0
open("/lib/tls/i586/libqmi-glib.so.0", O_RDONLY) = -1 ENOENT (No such
file or directory)
stat64("/lib/tls/i586", 0xbfdfb88c)     = -1 ENOENT (No such file or directory)
open("/lib/tls/libqmi-glib.so.0", O_RDONLY) = -1 ENOENT (No such file
or directory)
stat64("/lib/tls", 0xbfdfb88c)          = -1 ENOENT (No such file or directory)
open("/lib/i586/libqmi-glib.so.0", O_RDONLY) = -1 ENOENT (No such file
or directory)
stat64("/lib/i586", 0xbfdfb88c)         = -1 ENOENT (No such file or directory)
open("/lib/libqmi-glib.so.0", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/usr/lib/tls/i586/libqmi-glib.so.0", O_RDONLY) = -1 ENOENT (No
such file or directory)
stat64("/usr/lib/tls/i586", 0xbfdfb88c) = -1 ENOENT (No such file or directory)
open("/usr/lib/tls/libqmi-glib.so.0", O_RDONLY) = -1 ENOENT (No such
file or directory)
stat64("/usr/lib/tls", 0xbfdfb88c)      = -1 ENOENT (No such file or directory)
open("/usr/lib/i586/libqmi-glib.so.0", O_RDONLY) = -1 ENOENT (No such
file or directory)
stat64("/usr/lib/i586", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/usr/lib/libqmi-glib.so.0", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\320\263\2\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=4059652, ...}) = 0
mmap2(NULL, 1365660, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE,
3, 0) = 0xb7308000
mmap2(0xb7450000, 24576, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x148) = 0xb7450000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0po\1\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1331336, ...}) = 0
mmap2(NULL, 1345848, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE,
3, 0) = 0xb71bf000
mprotect(0xb7301000, 4096, PROT_NONE)   = 0
mmap2(0xb7302000, 12288, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x142) = 0xb7302000
mmap2(0xb7305000, 10552, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7305000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/i386-linux-gnu/libgmodule-2.0.so.0", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\360\16\0\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=13784, ...}) = 0
mmap2(NULL, 16568, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0xb71ba000
mmap2(0xb71bd000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2) = 0xb71bd000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libz.so.1", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\320\33\0\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=95896, ...}) = 0
mmap2(NULL, 98556, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0xb71a1000
mmap2(0xb71b8000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16) = 0xb71b8000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libselinux.so.1", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0pP\0\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=124904, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb71a0000
mmap2(NULL, 130140, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0xb7180000
mmap2(0xb719e000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1d) = 0xb719e000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libresolv.so.2", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\200&\0\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=71488, ...}) = 0
mmap2(NULL, 84040, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0xb716b000
mmap2(0xb717c000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x10) = 0xb717c000
mmap2(0xb717e000, 6216, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb717e000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/i386-linux-gnu/libgthread-2.0.so.0", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0p\5\0\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=5460, ...}) = 0
mmap2(NULL, 8216, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0xb7168000
mmap2(0xb7169000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0) = 0xb7169000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/i386-linux-gnu/libffi.so.5", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\340\21\0\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=37408, ...}) = 0
mmap2(NULL, 36712, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0xb715f000
mmap2(0xb7167000, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x8) = 0xb7167000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libpcre.so.3", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0`\22\0\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=248036, ...}) = 0
mmap2(NULL, 250764, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0xb7121000
mmap2(0xb715e000, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3c) = 0xb715e000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libpthread.so.0", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\260J\0\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=116748, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb7120000
mmap2(NULL, 98816, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0xb7107000
mmap2(0xb711c000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x14) = 0xb711c000
mmap2(0xb711e000, 4608, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb711e000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/librt.so.1", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\300\30\0\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=30684, ...}) = 0
mmap2(NULL, 33360, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0xb70fe000
mmap2(0xb7105000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6) = 0xb7105000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libdl.so.2", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0`\n\0\0004\0\0\0"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=9844, ...}) = 0
mmap2(NULL, 12408, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0xb70fa000
mmap2(0xb70fc000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1) = 0xb70fc000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb70f9000
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb70f8000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb70f8720,
limit:1048575, seg_32bit:1, contents:0, read_exec_only:0,
limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb70fc000, 4096, PROT_READ)   = 0
mprotect(0xb7105000, 4096, PROT_READ)   = 0
mprotect(0xb711c000, 4096, PROT_READ)   = 0
mprotect(0xb7169000, 4096, PROT_READ)   = 0
mprotect(0xb717c000, 4096, PROT_READ)   = 0
mprotect(0xb719e000, 4096, PROT_READ)   = 0
mprotect(0xb71b8000, 4096, PROT_READ)   = 0
mprotect(0xb71bd000, 4096, PROT_READ)   = 0
mprotect(0xb7302000, 8192, PROT_READ)   = 0
mprotect(0xb7551000, 4096, PROT_READ)   = 0
mprotect(0xb75a4000, 4096, PROT_READ)   = 0
mprotect(0xb7702000, 8192, PROT_READ)   = 0
mprotect(0xb772d000, 4096, PROT_READ)   = 0
munmap(0xb7706000, 33841)               = 0
set_tid_address(0xb70f8788)             = 24834
set_robust_list(0xb70f8790, 0xc)        = 0
futex(0xbfdfbe70, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1,
NULL, bfdfbe80) = -1 EAGAIN (Resource temporarily unavailable)
rt_sigaction(SIGRTMIN, {0xb710b540, [], SA_SIGINFO}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0xb710b9a0, [], SA_RESTART|SA_SIGINFO}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
uname({sys="Linux", node="MeshUnit13", ...}) = 0
statfs64("/sys/fs/selinux", 84, 0xbfdfbd7c) = -1 ENOENT (No such file
or directory)
statfs64("/selinux", 84, {f_type="EXT2_SUPER_MAGIC", f_bsize=4096,
f_blocks=1460703, f_bfree=424075, f_bavail=350820, f_files=366480,
f_ffree=186587, f_fsid={-398654445, -511116008}, f_namelen=255,
f_frsize=4096}) = 0
brk(0)                                  = 0x8200000
brk(0x8221000)                          = 0x8221000
open("/proc/filesystems", O_RDONLY|O_LARGEFILE) = 3
fstat64(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb770e000
read(3, "nodev\tsysfs\nnodev\trootfs\nnodev\tb"..., 1024) = 230
read(3, "", 1024)                       = 0
close(3)                                = 0
munmap(0xb770e000, 4096)                = 0
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=1534768, ...}) = 0
mmap2(NULL, 1534768, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb6f81000
close(3)                                = 0
gettimeofday({1354649235, 297847}, NULL) = 0
open("/usr/lib/i386-linux-gnu/charset.alias", O_RDONLY|O_LARGEFILE) =
-1 ENOENT (No such file or directory)
getresuid32([0], [0], [0])              = 0
getresgid32([0], [0], [0])              = 0
open("/usr/lib/i386-linux-gnu/gio/modules",
O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = -1 ENOENT (No
such file or directory)
open("/usr/share/locale/locale.alias", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=2570, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb770e000
read(3, "# Locale name alias data base.\n#"..., 4096) = 2570
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0xb770e000, 4096)                = 0
open("/usr/share/locale/de_DE.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) =
-1 ENOENT (No such file or directory)
open("/usr/share/locale/de_DE.utf8/LC_MESSAGES/libc.mo", O_RDONLY) =
-1 ENOENT (No such file or directory)
open("/usr/share/locale/de_DE/LC_MESSAGES/libc.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
open("/usr/share/locale/de.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
open("/usr/share/locale/de.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
open("/usr/share/locale/de/LC_MESSAGES/libc.mo", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=123193, ...}) = 0
mmap2(NULL, 123193, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb6f62000
close(3)                                = 0
open("/usr/lib/i386-linux-gnu/gconv/gconv-modules.cache", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=26064, ...}) = 0
mmap2(NULL, 26064, PROT_READ, MAP_SHARED, 3, 0) = 0xb6f5b000
close(3)                                = 0
futex(0xb7304a6c, FUTEX_WAKE_PRIVATE, 2147483647) = 0
open("/usr/share/locale/de_DE.UTF-8/LC_MESSAGES/messages.mo",
O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/de_DE.utf8/LC_MESSAGES/messages.mo", O_RDONLY)
= -1 ENOENT (No such file or directory)
open("/usr/share/locale/de_DE/LC_MESSAGES/messages.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
open("/usr/share/locale/de.UTF-8/LC_MESSAGES/messages.mo", O_RDONLY) =
-1 ENOENT (No such file or directory)
open("/usr/share/locale/de.utf8/LC_MESSAGES/messages.mo", O_RDONLY) =
-1 ENOENT (No such file or directory)
open("/usr/share/locale/de/LC_MESSAGES/messages.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
open("/usr/share/locale/de_DE.UTF-8/LC_MESSAGES/glib20.mo", O_RDONLY)
= -1 ENOENT (No such file or directory)
open("/usr/share/locale/de_DE.utf8/LC_MESSAGES/glib20.mo", O_RDONLY) =
-1 ENOENT (No such file or directory)
open("/usr/share/locale/de_DE/LC_MESSAGES/glib20.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
open("/usr/share/locale/de.UTF-8/LC_MESSAGES/glib20.mo", O_RDONLY) =
-1 ENOENT (No such file or directory)
open("/usr/share/locale/de.utf8/LC_MESSAGES/glib20.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
open("/usr/share/locale/de/LC_MESSAGES/glib20.mo", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=95470, ...}) = 0
mmap2(NULL, 95470, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb6f43000
close(3)                                = 0
open("/usr/lib/gio/modules",
O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = -1 ENOENT (No
such file or directory)
rt_sigaction(SIGINT, {0x80559d0, [INT], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGHUP, {0x80559d0, [HUP], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGTERM, {0x80559d0, [TERM], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
eventfd2(0, O_NONBLOCK|O_CLOEXEC)       = 3
write(3, "\1\0\0\0\0\0\0\0", 8)         = 8
mmap2(NULL, 8388608, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0xb6743000
mprotect(0xb6743000, 4096, PROT_NONE)   = 0
clone(child_stack=0xb6f42434,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,
parent_tidptr=0xb6f42bd8, {entry_number:6, base_addr:0xb6f42b70,
limit:1048575, seg_32bit:1, contents:0, read_exec_only:0,
limit_in_pages:1, seg_not_present:0, useable:1},
child_tidptr=0xb6f42bd8) = 24835
poll([{fd=3, events=POLLIN}], 1, -1)    = 1 ([{fd=3, revents=POLLIN}])
poll([{fd=3, events=POLLIN}], 1, -1)    = 1 ([{fd=3, revents=POLLIN}])
read(3, "\1\0\0\0\0\0\0\0", 16)         = 8
poll([{fd=3, events=POLLIN}], 1, -1)    = 1 ([{fd=3, revents=POLLIN}])
futex(0x820cfc0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
read(3, "\1\0\0\0\0\0\0\0", 16)         = 8
futex(0x820cfc0, FUTEX_WAKE_PRIVATE, 1) = 0
poll([{fd=3, events=POLLIN}], 1, 0)     = 0 (Timeout)
read(3, 0xbfdfbd6c, 16)                 = -1 EAGAIN (Resource
temporarily unavailable)
open("/dev/cdc-wdm0", O_RDWR|O_EXCL|O_NOCTTY|O_NONBLOCK) = 4
fstat64(4, {st_mode=S_IFCHR|S_ISVTX|0600, st_rdev=makedev(180, 176), ...}) = 0
fcntl64(4, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl64(4, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
write(3, "\1\0\0\0\0\0\0\0", 8)         = 8
poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 1
([{fd=3, revents=POLLIN}])
time(NULL)                              = 1354649235
open("/etc/localtime", O_RDONLY)        = 5
fstat64(5, {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
fstat64(5, {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb6742000
read(5, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\10\0\0\0\10\0\0\0\0"...,
4096) = 2309
_llseek(5, -28, [2281], SEEK_CUR)       = 0
read(5, "\nCET-1CEST,M3.5.0,M10.5.0/3\n", 4096) = 28
close(5)                                = 0
munmap(0xb6742000, 4096)                = 0
time(NULL)                              = 1354649235
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
time(NULL)                              = 1354649235
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
clock_gettime(CLOCK_MONOTONIC, {77039, 371533585}) = 0
write(4, "\1\17\0\0\0\0\0\1\"\0\4\0\1\1\0\2", 16) = 16
clock_gettime(CLOCK_MONOTONIC, {77039, 373309339}) = 0
poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 10627) = 1
([{fd=3, revents=POLLIN}])
read(3, "\1\0\0\0\0\0\0\0", 16)         = 8
clock_gettime(CLOCK_MONOTONIC, {77039, 375560770}) = 0
clock_gettime(CLOCK_MONOTONIC, {77039, 375974120}) = 0
poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 10625) = 1
([{fd=4, revents=POLLIN}])
read(3, 0xbfdfbd6c, 16)                 = -1 EAGAIN (Resource
temporarily unavailable)
clock_gettime(CLOCK_MONOTONIC, {77039, 377974964}) = 0
write(3, "\1\0\0\0\0\0\0\0", 8)         = 8
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
write(3, "\1\0\0\0\0\0\0\0", 8)         = 8
poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 1
([{fd=3, revents=POLLIN}])
time(NULL)                              = 1354649235
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 1
([{fd=3, revents=POLLIN}])
read(3, "\2\0\0\0\0\0\0\0", 16)         = 8
time(NULL)                              = 1354649235
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
clock_gettime(CLOCK_MONOTONIC, {77039, 387679871}) = 0
write(4, "\1\f\0\0\2\7\0\1\0%\0\0\0", 13) = 13
clock_gettime(CLOCK_MONOTONIC, {77039, 389177202}) = 0
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
time(NULL)                              = 1354649246
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
clock_gettime(CLOCK_MONOTONIC, {77050, 20630266}) = 0
write(4, "\1\20\0\0\0\0\0\2#\0\5\0\1\2\0\2\7", 17) = 17
clock_gettime(CLOCK_MONOTONIC, {77050, 22249319}) = 0
poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 9978) = 1
([{fd=4, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {77050, 25083863}) = 0
write(3, "\1\0\0\0\0\0\0\0", 8)         = 8
read(4, "\1)\0\200\2\7\2\1\0%\0\35\0\2\4\0\0\0\0\0\20\1\0000\21\17\00035714"...,
2048) = 66
time(NULL)                              = 1354649246
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "\1\0\0\0\0\0\0\0", 8)         = 8
poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 1
([{fd=3, revents=POLLIN}])
poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 1
([{fd=3, revents=POLLIN}])
read(3, "\2\0\0\0\0\0\0\0", 16)         = 8
time(NULL)                              = 1354649246
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
write(3, "\1\0\0\0\0\0\0\0", 8)         = 8
write(3, "\1\0\0\0\0\0\0\0", 8)         = 8
close(4)                                = 0
exit_group(1)                           = ?

Could you give me a hint in which sourcefile(s) I could start to look
for the timeout?

Kai


More information about the libqmi-devel mailing list