Menu
▾
▴
[Oorexx-bugs] [ oorexx-Bugs-2211806 ] rxqueue slow SVN 3642
|
From: SourceForge.net <no...@so...> - 2008-11-14 12:09:35
|
Bugs item #2211806, was opened at 2008-10-31 14:13 Message generated for change (Settings changed) made by tammer You can respond by visiting: https://sourceforge.net/tracker/?func=detail&atid=684730&aid=2211806&group_id=119701 Please note that this message will contain a full copy of the comment thread, including the initial issue submission, for this request, not just the latest update. Category: None Group: v4.0 >Status: Closed >Resolution: Fixed Priority: 5 Private: No Submitted By: Rainer Tammer (tammer) Assigned to: Nobody/Anonymous (nobody) Summary: rxqueue slow SVN 3642 Initial Comment: Hello, the SVN 3642 runs pretty good on AIX. With this version (and my AIX patch, diff attached) all unit tests are successfully (with one exception, see below). The strange thing is that (all?) operations which involve rxqueue are extremely slow. This was not the case with ooRexx 3.2.0. The only thing I have fond out so fare is that in rxqueue.cpp the call to RexxAddQueue() is slow. Any spontaneous ideas which might help to find the cause ?? Bye Rainer P.S.: Failing test: [failure] [20081031 13:50:51.349986] svn: r3371 Change date: 2008-09-21 06:33:29 +0200 Test: TEST_VALUE Class: VALUE.testGroup File: /daten/svn/ooRexx/test/trunk/ooRexx/base/bif/VALUE.testGroup Line: 346 Failed: assertSame Expected: [[], identityHash="102132152"] Actual: [[7], identityHash="115704721"] I rebuild and check this failure again, the last runs did not show this error. ---------------------------------------------------------------------- Comment By: Rainer Tammer (tammer) Date: 2008-11-03 08:23 Message: Hello, I just have tested 3653: Compiles on AIX: OK samples on AIX: OK unit test on AIX: OK (spped is good) Interpreter: REXX-ooRexx_4.0.0(MT) 6.03 3 Nov 2008 ooRexxUnit: 2.0.0_3.2.0oo Test: 1.0.0_4.0.0 Tests ran: 18630 Assertions: 550414 Failures: 0 Errors: 0 Skipped files: 21 File search: 00:00:11.565878 Suite construction: 00:00:06.157588 Test execution: 00:03:20.201165 Total time: 00:03:41.390638 Bye Rainer ---------------------------------------------------------------------- Comment By: Rainer Tammer (tammer) Date: 2008-11-02 09:33 Message: Hello, I just have tested 3649: Compile on AIX: OK samples on AIX: OK unit test: OK Interpreter: REXX-ooRexx_4.0.0(MT) 6.03 2 Nov 2008 ooRexxUnit: 2.0.0_3.2.0 ooTest: 1.0.0_4.0.0 Tests ran: 18630 Assertions: 550414 Failures: 0 Errors: 0 Skipped files: 21 File search: 00:01:01.266755 Suite construction: 00:00:06.363021 Test execution: 00:12:51.263734 Total time: 00:14:01.708759 The runtime has not changed. Bye Rainer ---------------------------------------------------------------------- Comment By: Rainer Tammer (tammer) Date: 2008-11-01 17:45 Message: Hello, jest checked with 3647... The run time for this sample: -------------------- sample ------------------------ #!/usr/bin/rexx value_back = '' new_queue = rxqueue('create', 'test_queue') old_queue = rxqueue('set', new_queue) address ksh 'ls -al | rxqueue' new_queue say 'Open Object Rexx has queued the filenames of the actual directory' say 'in the queue ' new_queue'. Number of Elements in the queue: ' queued() do while queued() > 0 parse pull element value_back = value_back || '0A'x || element end call rxqueue 'delete', new_queue call rxqueue 'set', old_queue say value_back exit value_back -------------------- sample ------------------------ # time test/speed.rex Open Object Rexx has queued the filenames of the actual directory in the queue test_queue. Number of Elements in the queue: 32 total 544 drwxr-xr-x 3 build system 4096 Nov 01 17:28 . drwxr-xr-x 4 build system 256 Oct 21 21:57 .. -rwxr-xr-x 1 build system 4674 Nov 01 17:27 ccreply.rex ... lines cut -rwxr-xr-x 1 build system 11240 Nov 01 17:27 complex.rex -rwxr-xr-x 1 build system 4536 Nov 01 17:27 factor.rex real 0m12.76s user 0m0.02s sys 0m0.03s Strangely neither user nor sys time is high... It looks like a timeout or something like that. It's like some thread is waiting for something. During a trace with truss I figured out the following ting: ls | truss -d -a -D -e -l -o rxqueue.truss rxqueue PID delta time call ------------------------------------------------------------------------------- ... 2826311: 0.0002: close(5)<------><------>= 0 2826311: 0.0002: getsockopt(4, 65535, 4104, 0x2FF22334, 0x2FF22330) = 0 2826311: 0.0002: connext(4, 0x2FF22390, 16) = 0 2826311: 0.0004: send(4, 0x2FF22510, 564, 0) = 564 2826311: 0.0002: recv(4, 0x2FF22510, 564, 0) = 564 2826311: 0.0002: send(4, 0x2FF22500, 564, 0) = 564 2826311: 0.0002: recv(4, 0x2FF22500, 564, 0) = 564 2826311: 0.0004: send(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.0002: recv(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.0002: kioctl(0, 22528, 0x00000000, 0x00000000) Err#25 ENOTTY 2826311: kread(0, " o o r e x x - c o n f i".., 4096) = 131 2826311: 0.0002: send(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.0002: send(4, 0x30000CF8, 13, 0) = 13 2826311: 0.0002: recv(4, 0x2FF226A0, 564, 0) = 564 <---------- big time difference 2826311: 0.1568: send(4, 0x2FF226A0, 564, 0) = 564 <---------- 2826311: 0.0002: send(4, 0x30000CF8, 4, 0) = 4 2826311: 0.0002: recv(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.1997: send(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.0002: send(4, 0x30000CF8, 8, 0) = 8 2826311: 0.0002: recv(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.1997: send(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.0002: send(4, 0x30000CF8, 8, 0) = 8 2826311: 0.0002: recv(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.1997: send(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.0002: send(4, 0x30000CF8, 5, 0) = 5 2826311: 0.0002: recv(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.1997: send(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.0002: send(4, 0x30000CF8, 9, 0) = 9 2826311: 0.0002: recv(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.1997: send(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.0002: send(4, 0x30000CF8, 5, 0) = 5 2826311: 0.0002: recv(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.1997: send(4, 0x2FF226A0, 564, 0) = 564 2826311: 0.0002: send(4, 0x30000CF8, 6, 0) = 6 ..... 2826311: 0.0002: send(4, 0x30000CF8, 10, 0) = 10 2826311: 0.0002: recv(4, 0x2FF226A0, 564, 0) = 564 2826311: kread(0, " o o r e x x - c o n f i".., 4096) = 0 2826311: 0.0004: thread_unlock(0x201C7C98) = 0 2826311: 0.0002: __loadx(0x04000000, 0x2FF220B0, 0x00000800, 0xD01329BC, 0x00000000) = 0x00000000 2826311: 0.0003: kfcntl(1, F_GETFL, 0x102B2047) = 2 2826311: 0.0003: kfcntl(2, F_GETFL, 0x102B2047) = 2 2826311: 0.0002: _exit(0) It looks like some timing problem with the sockets... Bye Rainer ---------------------------------------------------------------------- Comment By: Rainer Tammer (tammer) Date: 2008-11-01 09:10 Message: Hello, I just upgraded to SVN 3644. The test group QUEUED.testGroup is very slow. Especially test 5 , 6, are running several minutes. It really looks like queuing is the problem... Bye Rainer ---------------------------------------------------------------------- Comment By: Rainer Tammer (tammer) Date: 2008-10-31 14:21 Message: Hello, the failing test now runs OK. I just had an old rxapi running. Unfortunately this did not help with the performance problem. Bye Rainer ---------------------------------------------------------------------- You can respond by visiting: https://sourceforge.net/tracker/?func=detail&atid=684730&aid=2211806&group_id=119701 |