I am trying to debug a performance problem with my scanner. strace shows it
spending 5 seconds in a "select" call. (does this belong on the user list or
the devel list?).
Kernel 2.4.18
hpusbscsi module (modified to use my scanner VID/PID)
sg (generic scsi module)
vuescan 7.5.22 (scanning application)
Scanner: Minolta Elite II (USB)
What follows is the a compilation of the kern.log(>) and the strace output.
Note that the sg modules does an sg_poll, then there is a 5 second delay before
continuing. At the same time strace shows a select taking 5.14 seconds. This
select delay happens a lot throughout the scanner operation - this snippet is
just on startup. What in the world could be taking 5 seconds? Where should I
be focusing my effort? The hpusbscsi module, the sg modules, or the vuescan
application. I found the smoking gun - who is firing it?
Also note that select does actually succeed in 0.002697 seconds, so it only
sometimes (for some ops) takes 5 seconds.
22:04:33.314120 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.143719>
22:04:38.467995 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.140543>
22:04:43.613005 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <0.002697>
22:04:43.699571 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.147240>
22:04:49.196320 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.138597>
22:05:25.250140 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.142661>
22:05:30.417089 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <0.007371>
22:05:30.430805 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.145146>
22:05:38.959739 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.142547>
22:05:44.108621 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.840696>
-----
Timothy Jedlicka, [EMAIL PROTECTED], 1-630-713-4436, AOL-IM=bonzowork
Network Entomologist, Lucent Technologies, Testers For Hire
> 22:04:33 hpusbscsi.c: [simple_payload_callback:576] state= BEGINNING
> 22:04:33 hpusbscsi.c: [simple_payload_callback:579] state= WORKING
> 22:04:33 sg_poll: dev=0, res=0x104
> 22:04:38 hpusbscsi.c: [simple_done:535] Data transfer done
> 22:04:38 hpusbscsi.c: [simple_done:536] state= WORKING
> 22:04:38 hpusbscsi.c: [simple_done:542] state= WAIT
> 22:04:38 hpusbscsi.c: [control_interrupt_callback:435] Getting status byte 0
> 22:04:38 hpusbscsi.c: [control_interrupt_callback:448] state= WAIT
> 22:04:38 hpusbscsi.c: [control_interrupt_callback:452] state= FREE
> 22:04:38 sg...bh: dev=0, pack_id=0, res=0x0
> 22:04:38 sg_poll: dev=0, res=0x145
> 22:04:38 sg_read: dev=0, count=64
> 22:04:38 sg_read_xfer: num_xfer=36, iovec_count=0, k_use_sg=0
22:04:33.300884 open("/dev/sg0", O_RDWR|O_EXCL) = 7 <0.000240>
22:04:33.302741 ioctl(7, 0x2201, 0xbfffe60c) = 0 <0.000068>
22:04:33.303198 ioctl(7, 0x2282, 0x8226094) = 0 <0.000069>
22:04:33.303648 ioctl(7, 0x2275, 0xbfffe678) = 0 <0.000409>
22:04:33.308068 ioctl(7, 0x2272, 0xbfffe608) = 0 <0.000071>
22:04:33.308523 ioctl(7, 0x2276, 0xbfffe614) = 0 <0.000064>
22:04:33.308970 ioctl(7, 0x2271, 0xbfffe604) = 0 <0.000063>
22:04:33.309478 time(NULL) = 1020049473 <0.000010>
22:04:33.309664 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000012>
22:04:33.309897 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:04:33.310023 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000009>
22:04:33.310198 write(7, "S\0\0\0\375\377\377\377\6@\0\0$\0\0\0 \221R@,\260r@\370"...,
64) = 64 <0.00032$
| 00000 53 00 00 00 fd ff ff ff 06 40 00 00 24 00 00 00 S....... .@..$... |
| 00010 20 91 52 40 2c b0 72 40 f8 f1 36 08 c0 27 09 00 .R@,.r@ ..6..'.. |
| 00020 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
| 00030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
22:04:33.313908 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000013>
22:04:33.314120 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.143719>
22:04:38.458436 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000011>
22:04:38.458632 read(7, "S\0\0\0\375\377\377\377\6@\0\0$\0\0\0 \221R@,\260r@\370"...,
64) = 64 <0.000168$
| 00000 53 00 00 00 fd ff ff ff 06 40 00 00 24 00 00 00 S....... .@..$... |
| 00010 20 91 52 40 2c b0 72 40 f8 f1 36 08 c0 27 09 00 .R@,.r@ ..6..'.. |
| 00020 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
| 00030 00 00 00 00 00 00 00 00 14 14 00 00 00 00 00 00 ........ ........ |
22:04:38.460154 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000011>
22:04:38.460299 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000009>
22:04:38.460447 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:04:38.460567 time(NULL) = 1020049478 <0.000008>
22:04:38.460828 write(6, " 6214 5 INQUIRY "..., 199) = 199 <0.000050>
> 22:04:38 hpusbscsi.c: [simple_payload_callback:579] state= WORKING
> 22:04:38 sg_poll: dev=0, res=0x104
> 22:04:43 hpusbscsi.c: [control_interrupt_callback:435] Getting status byte 0
> 22:04:43 hpusbscsi.c: [control_interrupt_callback:448] state= WORKING
> 22:04:43 hpusbscsi.c: [control_interrupt_callback:457] state= PREMATURE
> 22:04:43 hpusbscsi.c: [simple_done:535] Data transfer done
> 22:04:43 hpusbscsi.c: [simple_done:536] state= PREMATURE
> 22:04:43 sg...bh: dev=0, pack_id=1, res=0x0
> 22:04:43 sg_poll: dev=0, res=0x145
> 22:04:43 sg_read: dev=0, count=64
> 22:04:43 sg_read_xfer: num_xfer=96, iovec_count=0, k_use_sg=0
22:04:38.465661 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000012>
22:04:38.465840 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:04:38.465964 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000009>
22:04:38.466112 write(7, "S\0\0\0\375\377\377\377\6@\0\0`\0\0\0 \221R@,\260r@\370"...,
64) = 64 <0.00043$
| 00000 53 00 00 00 fd ff ff ff 06 40 00 00 60 00 00 00 S....... .@..`... |
| 00010 20 91 52 40 2c b0 72 40 f8 f1 36 08 c0 27 09 00 .R@,.r@ ..6..'.. |
| 00020 01 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
| 00030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
22:04:38.467827 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000012>
22:04:38.467995 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.140543>
22:04:43.608828 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000012>
22:04:43.609016 read(7, "S\0\0\0\375\377\377\377\6@\0\0`\0\0\0 \221R@,\260r@\370"...,
64) = 64 <0.000163$
| 00000 53 00 00 00 fd ff ff ff 06 40 00 00 60 00 00 00 S....... .@..`... |
| 00010 20 91 52 40 2c b0 72 40 f8 f1 36 08 c0 27 09 00 .R@,.r@ ..6..'.. |
| 00020 01 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
| 00030 00 00 00 00 00 00 00 00 14 14 00 00 00 00 00 00 ........ ........ |
22:04:43.609593 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000011>
22:04:43.609735 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:04:43.609884 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:04:43.610006 time(NULL) = 1020049483 <0.000008>
22:04:43.610407 write(6, " 6219 5 INQUIRY "..., 379) = 379 <0.000050>
22:04:43.611804 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:04:43.611955 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:04:43.612078 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:04:43.612223 write(7, "S\0\0\0\375\377\377\377\n@\0\0\20\0\0\0
\221R@,\260r@\370"..., 64) = 64 <0.000$
| 00000 53 00 00 00 fd ff ff ff 0a 40 00 00 10 00 00 00 S....... .@...... |
| 00010 20 91 52 40 2c b0 72 40 f8 f1 36 08 c0 27 09 00 .R@,.r@ ..6..'.. |
| 00020 01 00 00 00 02 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
| 00030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
22:04:43.612860 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000011>
22:04:43.613005 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <0.002697>
22:04:43.615940 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:04:43.616099 read(7, "S\0\0\0\375\377\377\377\n@\0\0\20\0\0\0
\221R@,\260r@\370"..., 64) = 64 <0.0000$
| 00000 53 00 00 00 fd ff ff ff 0a 40 00 00 10 00 00 00 S....... .@...... |
| 00010 20 91 52 40 2c b0 72 40 f8 f1 36 08 c0 27 09 00 .R@,.r@ ..6..'.. |
| 00020 01 00 00 00 02 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
| 00030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
22:04:43.616445 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:04:43.616570 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:04:43.616714 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:04:43.616832 time(NULL) = 1020049483 <0.000009>
22:04:43.617037 write(6, " 6219 0 READ "..., 139) = 139 <0.000038>
> 22:04:43 hpusbscsi.c: [simple_payload_callback:576] state= BEGINNING
> 22:04:43 hpusbscsi.c: [simple_payload_callback:579] state= WORKING
> 22:04:48 hpusbscsi.c: [simple_done:535] Data transfer done
> 22:04:48 hpusbscsi.c: [simple_done:536] state= WORKING
> 22:04:48 hpusbscsi.c: [simple_done:542] state= WAIT
> 22:04:48 hpusbscsi.c: [control_interrupt_callback:435] Getting status byte 0
> 22:04:48 hpusbscsi.c: [control_interrupt_callback:448] state= WAIT
> 22:04:48 hpusbscsi.c: [control_interrupt_callback:452] state= FREE
> 22:04:48 sg...bh: dev=0, pack_id=6, res=0x0
> 22:04:48 sg_poll: dev=0, res=0x145
> 22:04:48 sg_read: dev=0, count=64
> 22:04:48 sg_read_xfer: num_xfer=36, iovec_count=0, k_use_sg=0
22:04:43.696570 open("/dev/sg0", O_RDWR|O_NONBLOCK) = 8 <0.000080>
22:04:43.696771 ioctl(8, 0x2276, 0xbfffe314) = 0 <0.000020>
22:04:43.696892 close(8) = 0 <0.000045>
22:04:43.697072 read(7, "", 4096) = 0 <0.000025>
22:04:43.697219 close(7) = 0 <0.000018>
22:04:43.697331 munmap(0x40015000, 4096) = 0 <0.000019>
22:04:43.697457 open("/dev/sg0", O_RDWR|O_EXCL) = 7 <0.000064>
22:04:43.697638 ioctl(7, 0x2201, 0xbfffe60c) = 0 <0.000017>
22:04:43.697757 ioctl(7, 0x2282, 0x8226094) = 0 <0.000017>
22:04:43.697867 ioctl(7, 0x2275, 0xbfffe678) = 0 <0.000125>
22:04:43.698086 ioctl(7, 0x2272, 0xbfffe608) = 0 <0.000016>
22:04:43.698194 ioctl(7, 0x2276, 0xbfffe614) = 0 <0.000016>
22:04:43.698298 ioctl(7, 0x2271, 0xbfffe604) = 0 <0.000016>
22:04:43.698427 time(NULL) = 1020049483 <0.000009>
22:04:43.698541 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000013>
22:04:43.698758 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:04:43.698880 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000009>
22:04:43.699024 write(7, "S\0\0\0\375\377\377\377\6@\0\0$\0\0\0 \221R@,\260r@\370"...,
64) = 64 <0.00010$
| 00000 53 00 00 00 fd ff ff ff 06 40 00 00 24 00 00 00 S....... .@..$... |
| 00010 20 91 52 40 2c b0 72 40 f8 f1 36 08 c0 27 09 00 .R@,.r@ ..6..'.. |
| 00020 01 00 00 00 06 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
| 00030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
22:04:43.699437 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:04:43.699571 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.147240>
22:04:48.847132 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000012>
22:04:48.847322 read(7, "S\0\0\0\375\377\377\377\6@\0\0$\0\0\0 \221R@,\260r@\370"...,
64) = 64 <0.000164$
| 00000 53 00 00 00 fd ff ff ff 06 40 00 00 24 00 00 00 S....... .@..$... |
| 00010 20 91 52 40 2c b0 72 40 f8 f1 36 08 c0 27 09 00 .R@,.r@ ..6..'.. |
| 00020 01 00 00 00 06 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
| 00030 00 00 00 00 00 00 00 00 14 14 00 00 00 00 00 00 ........ ........ |
22:04:48.847818 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:04:48.847950 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000011>
22:04:48.848098 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:04:48.848221 time(NULL) = 1020049488 <0.000008>
22:04:48.848482 write(6, " 6224 5 INQUIRY "..., 199) = 199 <0.000051>
22:04:49.159581 access("/home/bonzo/vue7522/vuescan.ini", F_OK) = 0 <0.000038>
22:04:49.159778 stat64("/home/bonzo/vue7522/vuescan.ini", {st_mode=S_IFREG|0644,
st_size=764, ...}) = 0 $
22:04:49.159986 open("/home/bonzo/vue7522/vuescan.ini", O_RDONLY) = 8 <0.000028>
22:04:49.160130 read(8, "[Files]\nOutputLogFile=1\n[Device]"..., 1024) = 764 <0.000031>
| 00000 5b 46 69 6c 65 73 5d 0a 4f 75 74 70 75 74 4c 6f [Files]. OutputLo |
| 00010 67 46 69 6c 65 3d 31 0a 5b 44 65 76 69 63 65 5d gFile=1. [Device] |
...
22:04:49.162239 brk(0x846e000) = 0x846e000 <0.000011>
22:04:49.162418 close(8) = 0 <0.000014>
22:04:49.162809 brk(0x846f000) = 0x846f000 <0.000012>
22:04:49.163661 brk(0x8470000) = 0x8470000 <0.000015>
22:04:49.165636 brk(0x8471000) = 0x8471000 <0.000017>
22:04:49.167391 brk(0x8472000) = 0x8472000 <0.000015>
22:04:49.168638 brk(0x8473000) = 0x8473000 <0.000014>
22:04:49.169144 brk(0x8475000) = 0x8475000 <0.000013>
22:04:49.170728 brk(0x8476000) = 0x8476000 <0.000015>
22:04:49.171776 brk(0x8477000) = 0x8477000 <0.000013>
22:04:49.173265 brk(0x8478000) = 0x8478000 <0.000015>
22:04:49.174951 brk(0x8479000) = 0x8479000 <0.000015>
22:04:49.176118 brk(0x847b000) = 0x847b000 <0.000014>
22:04:49.177733 brk(0x847c000) = 0x847c000 <0.000015>
22:04:49.178614 brk(0x847d000) = 0x847d000 <0.000015>
22:04:49.179503 brk(0x847e000) = 0x847e000 <0.000014>
22:04:49.180621 brk(0x847f000) = 0x847f000 <0.000016>
22:04:49.181745 brk(0x8480000) = 0x8480000 <0.000016>
22:04:49.182842 brk(0x8482000) = 0x8482000 <0.000016>
22:04:49.183341 brk(0x8483000) = 0x8483000 <0.000012>
22:04:49.184301 brk(0x8484000) = 0x8484000 <0.000015>
22:04:49.185767 brk(0x8485000) = 0x8485000 <0.000014>
22:04:49.186850 brk(0x8486000) = 0x8486000 <0.000013>
22:04:49.188306 brk(0x8487000) = 0x8487000 <0.000872>
22:04:49.190510 brk(0x8489000) = 0x8489000 <0.000015>
22:04:49.191524 time(NULL) = 1020049489 <0.000013>
22:04:49.191692 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000011>
22:04:49.191867 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:04:49.191993 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:04:49.192142 write(7, "S\0\0\0\375\377\377\377\6@\0\0$\0\0\0 \221R@,\260r@\370"...,
64) = 64 <0.00367$
| 00000 53 00 00 00 fd ff ff ff 06 40 00 00 24 00 00 00 S....... .@..$... |
| 00010 20 91 52 40 2c b0 72 40 f8 f1 36 08 c0 27 09 00 .R@,.r@ ..6..'.. |
| 00020 01 00 00 00 08 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
| 00030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
22:04:49.196165 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000011>
22:04:49.196320 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.138597>
22:04:54.335194 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000012>
22:04:54.335382 read(7, "S\0\0\0\375\377\377\377\6@\0\0$\0\0\0 \221R@,\260r@\370"...,
64) = 64 <0.001187$
| 00000 53 00 00 00 fd ff ff ff 06 40 00 00 24 00 00 00 S....... .@..$... |
| 00010 20 91 52 40 2c b0 72 40 f8 f1 36 08 c0 27 09 00 .R@,.r@ ..6..'.. |
| 00020 01 00 00 00 08 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
| 00030 00 00 00 00 00 00 00 00 14 14 00 00 00 00 00 00 ........ ........ |
22:04:54.336980 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000040>
22:04:54.337178 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:04:54.337327 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:04:54.337445 time(NULL) = 1020049494 <0.000008>
22:04:54.337706 write(6, " 6230 5 INQUIRY "..., 199) = 199 <0.000048>
22:05:25.245451 time(NULL) = 1020049525 <0.000008>
22:05:25.245598 time(NULL) = 1020049525 <0.000009>
22:05:25.245865 time(NULL) = 1020049525 <0.000009>
22:05:25.246324 gettimeofday({1020049525, 246389}, NULL) = 0 <0.000011>
22:05:25.246466 time(NULL) = 1020049525 <0.000009>
22:05:25.246591 time(NULL) = 1020049525 <0.000008>
22:05:25.246697 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000009>
22:05:25.246849 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:05:25.246966 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000009>
22:05:25.247108 write(7,
"S\0\0\0\377\377\377\377\6@\0\0\0\0\0\0\0\0\0\0,\260r@\370"..., 64) = 64 <0.002$
| 00000 53 00 00 00 ff ff ff ff 06 40 00 00 00 00 00 00 S....... .@...... |
| 00010 00 00 00 00 2c b0 72 40 f8 f1 36 08 c0 27 09 00 ....,.r@ ..6..'.. |
| 00020 01 00 00 00 2d 00 00 00 00 00 00 00 00 00 00 00 ....-... ........ |
| 00030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
22:05:25.249998 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000012>
22:05:25.250140 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.142661>
22:05:30.393069 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000012>
22:05:30.393258 read(7,
"S\0\0\0\377\377\377\377\6@\0\0\0\0\0\0\0\0\0\0,\260r@\370"..., 64) = 64 <0.0008$
| 00000 53 00 00 00 ff ff ff ff 06 40 00 00 00 00 00 00 S....... .@...... |
| 00010 00 00 00 00 2c b0 72 40 f8 f1 36 08 c0 27 09 00 ....,.r@ ..6..'.. |
| 00020 01 00 00 00 2d 00 00 00 00 00 00 00 00 00 00 00 ....-... ........ |
| 00030 00 00 00 00 00 00 00 00 14 14 00 00 00 00 00 00 ........ ........ |
22:05:30.394480 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:05:30.394613 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:05:30.394759 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:05:30.394877 time(NULL) = 1020049530 <0.000008>
22:05:30.395062 write(6, " 6266 5 TEST UNIT READY "..., 89) = 89 <0.000048>
22:05:30.417089 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <0.007371>
22:05:30.424751 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:05:30.424906 read(7, "S\0\0\0\376\377\377\377\n@\0\0\10\0\0\0
\221R@,\260r@\370"..., 64) = 64 <0.0008$
| 00000 53 00 00 00 fe ff ff ff 0a 40 00 00 08 00 00 00 S....... .@...... |
| 00010 20 91 52 40 2c b0 72 40 f8 f1 36 08 c0 27 09 00 .R@,.r@ ..6..'.. |
| 00020 01 00 00 00 2f 00 00 00 00 00 00 00 00 00 00 00 ..../... ........ |
| 00030 00 00 00 00 00 00 00 00 0a 00 00 00 00 00 00 00 ........ ........ |
22:05:30.426146 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:05:30.426280 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:05:30.426424 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:05:30.426541 time(NULL) = 1020049530 <0.000008>
22:05:30.426730 write(6, " 6266 0 SEND "..., 115) = 115 <0.000036>
| 00000 20 36 32 36 36 20 20 20 20 30 20 53 45 4e 44 20 6266 0 SEND |
| 00010 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 |
| 00020 20 20 20 20 20 32 61 20 20 30 20 38 37 20 20 30 2a 0 87 0 |
| 00030 20 20 30 20 20 30 20 20 30 20 20 30 20 20 38 20 0 0 0 0 8 |
| 00040 20 30 20 20 20 20 20 20 20 30 30 30 30 30 30 30 0 0000000 |
| 00050 38 20 30 32 30 30 20 57 20 20 32 20 20 31 20 20 8 0200 W 2 1 |
| 00060 36 20 20 30 20 20 30 20 20 64 20 20 30 20 20 30 6 0 0 d 0 0 |
| 00070 20 0d 0a .. |
22:05:30.427212 time(NULL) = 1020049530 <0.000008>
22:05:30.427342 time(NULL) = 1020049530 <0.000008>
22:05:30.427448 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:05:30.427597 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:05:30.427717 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000009>
22:05:30.427859 write(7,
"S\0\0\0\377\377\377\377\6@\0\0\0\0\0\0\0\0\0\0,\260r@\370"..., 64) = 64 <0.002$
| 00000 53 00 00 00 ff ff ff ff 06 40 00 00 00 00 00 00 S....... .@...... |
| 00010 00 00 00 00 2c b0 72 40 f8 f1 36 08 c0 27 09 00 ....,.r@ ..6..'.. |
| 00020 01 00 00 00 30 00 00 00 00 00 00 00 00 00 00 00 ....0... ........ |
| 00030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
22:05:30.430668 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:05:30.430805 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.145146>
22:05:35.576219 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000011>
22:05:35.576405 read(7,
"S\0\0\0\377\377\377\377\6@\0\0\0\0\0\0\0\0\0\0,\260r@\370"..., 64) = 64 <0.0009$
| 00000 53 00 00 00 ff ff ff ff 06 40 00 00 00 00 00 00 S....... .@...... |
| 00010 00 00 00 00 2c b0 72 40 f8 f1 36 08 c0 27 09 00 ....,.r@ ..6..'.. |
| 00020 01 00 00 00 30 00 00 00 00 00 00 00 00 00 00 00 ....0... ........ |
| 00030 00 00 00 00 00 00 00 00 14 14 00 00 00 00 00 00 ........ ........ |
22:05:35.577666 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000011>
22:05:35.577799 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000009>
22:05:35.577944 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:05:35.578062 time(NULL) = 1020049535 <0.000009>
22:05:35.578249 write(6, " 6271 5 TEST UNIT READY "..., 89) = 89 <0.000048>
22:05:38.956393 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:05:38.956541 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:05:38.956659 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000009>
22:05:38.956801 write(7,
"S\0\0\0\377\377\377\377\6@\0\0\0\0\0\0\0\0\0\0,\260r@\370"..., 64) = 64 <0.002$
| 00000 53 00 00 00 ff ff ff ff 06 40 00 00 00 00 00 00 S....... .@...... |
| 00010 00 00 00 00 2c b0 72 40 f8 f1 36 08 c0 27 09 00 ....,.r@ ..6..'.. |
| 00020 01 00 00 00 37 00 00 00 00 00 00 00 00 00 00 00 ....7... ........ |
| 00030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
22:05:38.959603 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:05:38.959739 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.142547>
22:05:44.102554 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000011>
22:05:44.102744 read(7,
"S\0\0\0\377\377\377\377\6@\0\0\0\0\0\0\0\0\0\0,\260r@\370"..., 64) = 64 <0.0008$
| 00000 53 00 00 00 ff ff ff ff 06 40 00 00 00 00 00 00 S....... .@...... |
| 00010 00 00 00 00 2c b0 72 40 f8 f1 36 08 c0 27 09 00 ....,.r@ ..6..'.. |
| 00020 01 00 00 00 37 00 00 00 00 00 00 00 00 00 00 00 ....7... ........ |
| 00030 00 00 00 00 00 00 00 00 1e 14 00 00 00 00 00 00 ........ ........ |
22:05:44.103934 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:05:44.104065 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:05:44.104210 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:05:44.104326 time(NULL) = 1020049544 <0.000008>
22:05:44.104508 write(6, " 6280 6 RESERVE UNIT "..., 89) = 89 <0.000047>
22:05:44.104508 write(6, " 6280 6 RESERVE UNIT "..., 89) = 89 <0.000047>
| 00000 20 36 32 38 30 20 20 20 20 36 20 52 45 53 45 52 6280 6 RESER |
| 00010 56 45 20 55 4e 49 54 20 20 20 20 20 20 20 20 20 VE UNIT |
| 00020 20 20 20 20 20 31 36 20 20 30 20 20 30 20 20 30 16 0 0 0 |
| 00030 20 20 30 20 20 30 20 20 20 20 20 20 20 20 20 20 0 0 |
| 00040 20 20 20 20 20 20 20 20 20 30 30 30 30 30 30 30 0000000 |
| 00050 30 20 30 32 30 30 20 0d 0a 0 0200 . . |
22:05:44.105011 time(NULL) = 1020049544 <0.000009>
22:05:44.105159 time(NULL) = 1020049544 <0.000008>
22:05:44.105265 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000009>
22:05:44.105414 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:05:44.105533 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:05:44.105677 write(7,
"S\0\0\0\377\377\377\377\6@\0\0\0\0\0\0\0\0\0\0,\260r@\370"..., 64) = 64 <0.001$
| 00000 53 00 00 00 ff ff ff ff 06 40 00 00 00 00 00 00 S....... .@...... |
| 00010 00 00 00 00 2c b0 72 40 f8 f1 36 08 c0 27 09 00 ....,.r@ ..6..'.. |
| 00020 01 00 00 00 38 00 00 00 00 00 00 00 00 00 00 00 ....8... ........ |
| 00030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ........ ........ |
22:05:44.108481 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:05:44.108621 select(8, [7], NULL, NULL, NULL) = 1 (in [7]) <5.840696>
22:05:49.949589 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000012>
22:05:49.949777 read(7,
"S\0\0\0\377\377\377\377\6@\0\0\0\0\0\0\0\0\0\0,\260r@\370"..., 64) = 64 <0.0009$
| 00000 53 00 00 00 ff ff ff ff 06 40 00 00 00 00 00 00 S....... .@...... |
| 00010 00 00 00 00 2c b0 72 40 f8 f1 36 08 c0 27 09 00 ....,.r@ ..6..'.. |
| 00020 01 00 00 00 38 00 00 00 00 00 00 00 00 00 00 00 ....8... ........ |
| 00030 00 00 00 00 00 00 00 00 da 16 00 00 00 00 00 00 ........ ........ |
22:05:49.951011 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000010>
22:05:49.951142 rt_sigprocmask(SIG_BLOCK, ~[], [RTMIN], 8) = 0 <0.000010>
22:05:49.951284 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0 <0.000009>
22:05:49.951400 time(NULL) = 1020049549 <0.000008>
22:05:49.951581 write(6, " 6285 5 SCAN "..., 89) = 89 <0.000051>
| 00000 20 36 32 38 35 20 20 20 20 35 20 53 43 41 4e 20 6285 5 SCAN |
