soul er cputime eater
in [TCL]
|
From: Uwe Klein on 4 May 2010 09:32 I have some problems with a wish script running wild. It reads from a tcp socket via expect. a lot of traces but no use of [after]. This trouble rings a faint bell for me, but I can't remember what it was. strace produces: gettimeofday({1272981751, 253858}, NULL) = 0 gettimeofday({1272981751, 254108}, NULL) = 0 gettimeofday({1272981751, 254384}, NULL) = 0 read(3, 0x8063c48, 4096) = -1 EAGAIN (Resource temporarily unavailable) select(10, [3 5 6 9], [], [9], NULL) = 1 (in [9]) read(3, 0x8063c48, 4096) = -1 EAGAIN (Resource temporarily unavailable) read(9, "!AIVDM,1,1,,A,13ckuS00010`ch`IJ;"..., 4096) = 49 write(7, "!AIVDM,1,1,,A,13ckuS00010`ch`IJ;"..., 49) = 49 gettimeofday({1272981751, 276719}, NULL) = 0 .... ~ about _330 similar lines at intervals of ~270us_ snipped. .... gettimeofday({1272981751, 368676}, NULL) = 0 read(3, 0x8063c48, 4096) = -1 EAGAIN (Resource temporarily unavailable) select(10, [3 5 6 9], [], [9], NULL) = 1 (in [9]) read(3, 0x8063c48, 4096) = -1 EAGAIN (Resource temporarily unavailable) read(9, "$IIDBT,,f,,M,,F*3F\r\n$IIMTA,020,C"..., 4096) = 110 write(7, "$IIDBT,,f,,M,,F*3F\r\n$IIMTA,020,C"..., 110) = 110 gettimeofday({1272981751, 390932}, NULL) = 0 gettimeofday({1272981751, 391645}, NULL) = 0 gettimeofday({1272981751, 392142}, NULL) = 0 model name : Intel(R) Atom(TM) CPU N270 @ 1.60GHz stepping : 2 cpu MHz : 800.000 cache size : 512 KB expect 5.44.1.11 tcl/tk 8.5.7 from SuSE 11.2 distribution the same script run on another machine ( x86_64 , same distribution) produces completely different output: select(10, [3 5 6 9], [], [9], NULL) = 1 (in [9]) read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) read(9, "!AIVDM,1,1,,B,139a>@RP00PNq<0MKo"..., 4096) = 49 write(7, "!AIVDM,1,1,,B,139a>@RP00PNq<0MKo"..., 49) = 49 read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) select(10, [3 5 6 9], [], [9], {0, 0}) = 0 (Timeout) read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) poll([{fd=3, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=3, revents=POLLOUT}]) writev(3, [{"5\30\4\0\321\210\300\1x\1\300\1M\0h\1F\7\5\0\321\210\300\1\2\0\300\1\0\0\0\0"..., 16384}, {NULL, 0}, {"", 0}], 3) = 16384 read(3, "\16\0H\265x\1\300\1\0\0>@\0\0\0\0\2000\6h\377\177\0\0\0\0\0\0\0\0\0\0"..., 4096) = 320 read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) poll([{fd=3, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=3, revents=POLLOUT}]) writev(3, [{"\5\30\4\0\27\0\221\0\3\23\21\33\30\0h\1\230\7\2\0\323\263\300\1\230\4\5\0\324\263\300\1"..., 5184}, {NULL, 0}, {"", 0}], 3) = 5184 read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavai select(10, [3 5 6 9], [], [9], {0, 0}) = 0 (Timeout) read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) select(10, [3 5 6 9], [], [9], NULL) = 1 (in [3]) read(3, "\16\0\322\267t\1\300\1\0\0>@\0\0\0\0\2000\6h\377\177\0\0\0\0\0\0\0\0\0\0"..., 4096) = 192 read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) rt_sigaction(SIGPIPE, {0x1, [PIPE], SA_RESTORER|SA_RESTART, 0x7f18ffd0c560}, {0x1, [PIPE], SA_RESTORER|SA_RESTART, 0x7f18ffd0c560}, 8) = 0 poll([{fd=3, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=3, revents=POLLOUT}]) writev(3, [{"\177\30\1\0", 4}, {NULL, 0}, {"", 0}], 3) = 4 read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) rt_sigaction(SIGPIPE, {0x1, [PIPE], SA_RESTORER|SA_RESTART, 0x7f18ffd0c560}, {0x1, [PIPE], SA_RESTORER|SA_RESTART, 0x7f18ffd0c560}, 8) = 0 read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) select(10, [3 5 6 9], [], [9], NULL) = 1 (in [9]) read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) read(9, "$GPDTM,W84,,00.0000,N,00.0000,E,"..., 4096) = 41 write(7, "$GPDTM,W84,,00.0000,N,00.0000,E,"..., 41) = 41
From: Alexandre Ferrieux on 4 May 2010 10:01 On May 4, 3:32 pm, Uwe Klein <uwe_klein_habertw...(a)t-online.de> wrote: > I have some problems with a wish script running wild. > It reads from a tcp socket via expect. > a lot of traces but no use of [after]. > > This trouble rings a faint bell for me, but I can't remember what it was. > > strace produces: > > gettimeofday({1272981751, 253858}, NULL) = 0 > gettimeofday({1272981751, 254108}, NULL) = 0 > gettimeofday({1272981751, 254384}, NULL) = 0 > read(3, 0x8063c48, 4096) = -1 EAGAIN (Resource temporarily unavailable) > select(10, [3 5 6 9], [], [9], NULL) = 1 (in [9]) > read(3, 0x8063c48, 4096) = -1 EAGAIN (Resource temporarily unavailable) > read(9, "!AIVDM,1,1,,A,13ckuS00010`ch`IJ;"..., 4096) = 49 > write(7, "!AIVDM,1,1,,A,13ckuS00010`ch`IJ;"..., 49) = 49 > gettimeofday({1272981751, 276719}, NULL) = 0 > ... > ~ about _330 similar lines at intervals of ~270us_ snipped. > ... > gettimeofday({1272981751, 368676}, NULL) = 0 > read(3, 0x8063c48, 4096) = -1 EAGAIN (Resource temporarily unavailable) > select(10, [3 5 6 9], [], [9], NULL) = 1 (in [9]) > read(3, 0x8063c48, 4096) = -1 EAGAIN (Resource temporarily unavailable) > read(9, "$IIDBT,,f,,M,,F*3F\r\n$IIMTA,020,C"..., 4096) = 110 > write(7, "$IIDBT,,f,,M,,F*3F\r\n$IIMTA,020,C"..., 110) = 110 > gettimeofday({1272981751, 390932}, NULL) = 0 > gettimeofday({1272981751, 391645}, NULL) = 0 > gettimeofday({1272981751, 392142}, NULL) = 0 > > model name : Intel(R) Atom(TM) CPU N270 @ 1.60GHz > stepping : 2 > cpu MHz : 800.000 > cache size : 512 KB > > expect 5.44.1.11 > tcl/tk 8.5.7 > from SuSE 11.2 distribution > > the same script run on another machine ( x86_64 , same distribution) > produces completely different output: > > select(10, [3 5 6 9], [], [9], NULL) = 1 (in [9]) > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) > read(9, "!AIVDM,1,1,,B,139a>@RP00PNq<0MKo"..., 4096) = 49 > write(7, "!AIVDM,1,1,,B,139a>@RP00PNq<0MKo"..., 49) = 49 > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) > select(10, [3 5 6 9], [], [9], {0, 0}) = 0 (Timeout) > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) > poll([{fd=3, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=3, revents=POLLOUT}]) > writev(3, [{"5\30\4\0\321\210\300\1x\1\300\1M\0h\1F\7\5\0\321\210\300\1\2\0\300\1\0\0 \0\0"..., > 16384}, {NULL, 0}, {"", 0}], 3) = 16384 > read(3, "\16\0H\265x\1\300\1\0\0>@\0\0\0\0\2000\6h\377\177\0\0\0\0\0\0\0\0\0\0"..., 4096) = 320 > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) > poll([{fd=3, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=3, revents=POLLOUT}]) > writev(3, > [{"\5\30\4\0\27\0\221\0\3\23\21\33\30\0h\1\230\7\2\0\323\263\300\1\230\4\5\ 0\324\263\300\1"..., > 5184}, {NULL, 0}, {"", 0}], 3) = 5184 > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavai > select(10, [3 5 6 9], [], [9], {0, 0}) = 0 (Timeout) > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) > select(10, [3 5 6 9], [], [9], NULL) = 1 (in [3]) > read(3, "\16\0\322\267t\1\300\1\0\0>@\0\0\0\0\2000\6h\377\177\0\0\0\0\0\0\0\0\0\0". .., 4096) = 192 > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) > rt_sigaction(SIGPIPE, {0x1, [PIPE], SA_RESTORER|SA_RESTART, 0x7f18ffd0c560}, {0x1, [PIPE], > SA_RESTORER|SA_RESTART, 0x7f18ffd0c560}, 8) = 0 > poll([{fd=3, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=3, revents=POLLOUT}]) > writev(3, [{"\177\30\1\0", 4}, {NULL, 0}, {"", 0}], 3) = 4 > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) > rt_sigaction(SIGPIPE, {0x1, [PIPE], SA_RESTORER|SA_RESTART, 0x7f18ffd0c560}, {0x1, [PIPE], > SA_RESTORER|SA_RESTART, 0x7f18ffd0c560}, 8) = 0 > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) > select(10, [3 5 6 9], [], [9], NULL) = 1 (in [9]) > read(3, 0x62b9d4, 4096) = -1 EAGAIN (Resource temporarily unavailable) > read(9, "$GPDTM,W84,,00.0000,N,00.0000,E,"..., 4096) = 41 > write(7, "$GPDTM,W84,,00.0000,N,00.0000,E,"..., 41) = 41 For the differing behavior between the two distribs I have no clue, but for the symptom 'busyloop calling gettimeofday', this rings the following bell: Bug #2904418 -- One millisecond of busyloop in [after] https://sourceforge.net/tracker/?func=detail&aid=2904418&group_id=10894&atid=110894 Now you said you were not calling [after]. Could it be that internally, Expect does call the underlying C function ? -Alex
From: Uwe Klein on 4 May 2010 10:35 Alexandre Ferrieux wrote: > For the differing behavior between the two distribs I have no clue, Hi Alex, thanks. It is actually the same distribution openSUSE 11.2 (i586) VERSION = 11.2 atom single core openSUSE 11.2 (x86_64) VERSION = 11.2 amd64 dual core > but for the symptom 'busyloop calling gettimeofday', this rings the > following bell: > > Bug #2904418 -- One millisecond of busyloop in [after] > > https://sourceforge.net/tracker/?func=detail&aid=2904418&group_id=10894&atid=110894 > > Now you said you were not calling [after]. Could it be that > internally, Expect does call the underlying C function ? Not that i know of. and the NMEA sentences each come in a single TCP packet. My assumption is that expect sees the input(line) as one lump and not bytewise like on a serial line. I use expect_background to evaluate input into global arrays. The rest of the application is linked in via traces. After all scripts are read the interpreter sits in vwait. my ancient system with ancient tcl and expect runs the same scripts with the same input data rate at ~1.5% cpu while the newfangled systems take ~15% for the dual core and 50% for the atom box.
From: Uwe Klein on 4 May 2010 11:09 Uwe Klein wrote: > gettimeofday({1272981751, 276719}, NULL) = 0 > ... > ~ about _330 similar lines at intervals of ~270us_ snipped. > ... > gettimeofday({1272981751, 368676}, NULL) = 0 expr ( 368676 - 276719 ) / 1000.0 us/ms 91.957ms looks like the busyloop runs for the complete time between two messages. uwe
From: Alexandre Ferrieux on 4 May 2010 12:19 On May 4, 5:09 pm, Uwe Klein <uwe_klein_habertw...(a)t-online.de> wrote: > Uwe Klein wrote: > > gettimeofday({1272981751, 276719}, NULL) = 0 > > ... > > ~ about _330 similar lines at intervals of ~270us_ snipped. > > ... > > gettimeofday({1272981751, 368676}, NULL) = 0 > > expr ( 368676 - 276719 ) / 1000.0 us/ms > 91.957ms > looks like the busyloop runs for the complete time > between two messages. > > uwe Please can you redo the strace with -tt ? -Alex
|
Next
|
Last
Pages: 1 2 Prev: Apache Rivet 2.0 Released Next: [newbie] Packing www + SQLite + TCL in one binary? |