#553 rxqueue slow SVN 3642

v4.0
closed
nobody
None
5
2012-08-14
2008-10-31
No

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.

Discussion

  • Rainer Tammer

    Rainer Tammer - 2008-10-31

    ooRexx-3642-V1.patch

     
  • Rainer Tammer

    Rainer Tammer - 2008-10-31

    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

     
  • Rainer Tammer

    Rainer Tammer - 2008-11-01

    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

     
  • Rainer Tammer

    Rainer Tammer - 2008-11-01

    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

     
  • Rainer Tammer

    Rainer Tammer - 2008-11-02

    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

     
  • Rainer Tammer

    Rainer Tammer - 2008-11-03

    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

     


Anonymous

Cancel  Add attachments





Get latest updates about Open Source Projects, Conferences and News.

Sign up for the SourceForge newsletter:

JavaScript is required for this form.





No, thanks