Applying your patch and re-running the problematic test-cases, it seems to be
indeed the case that
the problem is solved! Many thanks!
---rony
On 30.04.2017 13:00, Rony G. Flatscher wrote:
> On 30.04.2017 12:53, Rick McGuire wrote:
>> I want to verify something first. In this scenario, Rexx code makes a call
>> to a Java method
>> (i.e., the parser) which then makes a lot of callbacks all on the same
>> thread?
> Yes.
>
>> If so, then I think I might see where the problem could be. The code that
>> handles nested thread
>> attaches (that is, attaching to a thread that already exists) appears to
>> hold on to any allocated
>> objects until it returns to the original exit point (in your case, the
>> initial call to the parser).
>>
>> This may take a little while to figure out the details of a fix, but I at
>> least know where to
>> start. You might want to open a bug indicating there appears to be an
>> AttachThread()/DetachThread() memory leak.
> Opened a bug: <https://sourceforge.net/p/oorexx/bugs/1445/>.
>
> ---rony
>
>>
>> On Sun, Apr 30, 2017 at 6:38 AM, Rony G. Flatscher <rony.flatsc...@wu.ac.at
>> <mailto:rony.flatsc...@wu.ac.at>> wrote:
>>
>> Having slept I went over the debug statements, just to learn that I
>> concluded wrongly
>> yesterday: the reference decreases did not come from the Rexx objects
>> with uninits, but from
>> the Java side! :(
>>
>> With new debug statements on the Rexx side (in the destructores) it is
>> clear that no proxy
>> Rexx object turns into garbage before the program gets interrupted with
>> a syntax error.
>>
>> Will start over analyzing the codepaths, creating debug programs and
>> report back, once I am
>> done, which might take a day or two.
>>
>> ---rony
>>
>>
>> On 29.04.2017 21:53, Rick McGuire wrote:
>>>
>>>
>>> On Sat, Apr 29, 2017 at 3:43 PM, Rony G. Flatscher
>>> <rony.flatsc...@wu.ac.at
>>> <mailto:rony.flatsc...@wu.ac.at>> wrote:
>>>
>>> The class object (for the BSF class and also its subclasses) is
>>> (get) created in the
>>> BSF.CLS package, which gets required. So it (and its subclasses)
>>> should get created only
>>> once in this test case.
>>>
>>> The ooRexx peer objects are instances of the .BSF class, which
>>> defines an uninit method.
>>>
>>> Ad interpreter safepoints:
>>>
>>> * in this case there is a pending external Rexx function call
>>> that kicks of the SAX
>>> parser's parsing and only will return after the SAX parser
>>> concluded its work,
>>> * in the meantime each callback from the SAX parser will cause a
>>> call via JNI to Rexx,
>>> where each such callback will do an AttachThread() in native
>>> code and before
>>> returning a DetachThread().
>>>
>>> The uninits run, so these interpreter safepoints should be reached.
>>>
>>> The return from the ooRexx code at the end of the event call is one
>>> safepoint, but the
>>> arguments you passed will still be protected at this point. However,
>>> these objects will not
>>> be processed until the next time a garbage collection is required and
>>> then not until the
>>> next uninit point is hit.
>>>
>>>
>>>
>>> ---
>>>
>>> Maybe one more thing: the ooRexx peer objects that get created in
>>> native code are stored
>>> in a RexxArray object as they server as arguments for the
>>> SendMessage() function. So I
>>> assume (pure speculation!) that first the RexxArray object needs to
>>> get destroyed in
>>> order for its contained objects to become eligible for destruction.
>>> Maybe that explains
>>> why the Rexx peer objects currently do not get their uninits run at
>>> a much faster pace.
>>>
>>>
>>> I doubt this causes much of the delay, since these objects don't get
>>> moved to the uninit
>>> queue until the next time it is necessary to run the garbage collector.
>>> It is highly
>>> unlikely that more than a few objects would be affected by this, but
>>> you might give it a
>>> try and see what happens.
>>>
>>> Rick
>>>
>>>
>>> ---rony
>>>
>>>
>>>
>>> On 29.04.2017 21:32, Rick McGuire wrote:
>>>> Running the garbage collector will not force the uninit methods to
>>>> be run. When the
>>>> garbage collector runs, any newly dead objects with uninit methods
>>>> are marked as being
>>>> ready to have the uninit method run. At some later time, when the
>>>> interpreter is at a
>>>> safe point, then the objects with pending uninit methods will be
>>>> processed. These are
>>>> major boundaries such as return from a method or call or thread
>>>> termination.
>>>>
>>>> Since you are creating class objects, things can get delayed even
>>>> further since the
>>>> class object will not become "dead" until all of its instances are
>>>> first "dead". It
>>>> then gets moved to the uninit queue for processing.
>>>>
>>>> Rick
>>>>
>>>> On Sat, Apr 29, 2017 at 3:11 PM, Rony G. Flatscher
>>>> <rony.flatsc...@wu.ac.at
>>>> <mailto:rony.flatsc...@wu.ac.at>> wrote:
>>>>
>>>> Today, I have started to analyze the code-paths through
>>>> BSF4ooRexx (Java, c++,
>>>> ooRexx-package BSF.CLS).
>>>>
>>>> As I have not found any "obvious" cause for the observed
>>>> behaviour yet, I have
>>>> started to analyse the changes in the Java registry (that I
>>>> have full control of).
>>>>
>>>> Maybe first a sketch, how Java objects get proxied by ooRexx
>>>> objects:
>>>>
>>>> * a Java object that is to be sent to ooRexx as a return or
>>>> argument value will
>>>> get stored together with a reference counter in a Java
>>>> registry (using a
>>>> ConcurrentHashMap), the index is a string which will get
>>>> passed on to Rexx
>>>> instead of the Java object,
>>>> * the Rexx side will create an instance of the class .BSF
>>>> (or a subclass of it)
>>>> supplying the Java object's index string which is used as
>>>> the objecname for the
>>>> ooRexx peer object
>>>> o The BSF class has a destructor method (uninit) which
>>>> will cause a call to
>>>> the Java side to reduce the Java object's reference
>>>> counter; if the Java
>>>> reference counter drops to 0 the Java object will be
>>>> removed from the Java
>>>> registry
>>>>
>>>> Running the SAX-example serving as the test case until 250
>>>> startElement
>>>> SAX-callbacks (each callback from Java to Rexx will cause an
>>>> AttachThread(),
>>>> creating the ooRexx peer objects for the arguments, sending
>>>> the Rexx message, upon
>>>> return doing a DetachThread()) have been carried out (in
>>>> addition there are plenty
>>>> of other SAX-callbacks) and using debug statements for adding
>>>> and removing entries
>>>> to/from the Java registry, this is what I can observe:
>>>>
>>>> * the ooRexx destructors run,
>>>> * *however* the rate of new ooRexx peer objects that get
>>>> created (by Java objects
>>>> that are sent to Rexx) is much higher than the rate of
>>>> ooRexx peer objects that
>>>> get garbage collected by ooRexx, which causes a continuous
>>>> increase in Rexx
>>>> objects over time
>>>> o indeed, the ooRexx peer objects get destroyed
>>>> eventually, causing the Java
>>>> refcounters to be decreased
>>>> + it seems that not all ooRexx peer objects that
>>>> have turned into garbage
>>>> get destroyed in the garbage collection runs
>>>> o still (hence), the amount of ooRexx peer objects
>>>> increases quickly at
>>>> runtime as the flux of callbacks from Java continues
>>>> * at the end of the program (in this case forcing an error
>>>> to stop it by issuing
>>>> a 'say 1/0') all uninits run the reference counters on the
>>>> Java objects in the
>>>> Java registry drop to 0!
>>>>
>>>> Is there a way in ooRexx to have the garbage collector be run
>>>> (like in Java's
>>>> System.gc() or Runtime.getRuntime.gc())?
>>>>
>>>> Such a possibility might help to debug/tame this "run-away"
>>>> scenario.
>>>>
>>>> ---rony
>>>>
>>>>
>>>>
>>>> On 27.04.2017 16:56, Rony G. Flatscher wrote:
>>>>>
>>>>> Thank you! Will report back, once I concluded the analysis,
>>>>> which may take a while.
>>>>>
>>>>> ---rony
>>>>>
>>>>>
>>>>> On 27.04.2017 16:53, Rick McGuire wrote:
>>>>>> The memory manager will force any pending uninits to be run
>>>>>> before it gives up
>>>>>> and issues the out of resources error messages. I really
>>>>>> suspect something in the
>>>>>> way your code is creating the proxies and tracking them is
>>>>>> preventing the objects
>>>>>> from being identified as dead objects, so these objects will
>>>>>> just keep
>>>>>> accumulating. The more live objects locked in memory, the
>>>>>> longer a GC cycle will
>>>>>> take because there is a larger live set to mark.
>>>>>>
>>>>>> Rick
>>>>>>
>>>>>> On Thu, Apr 27, 2017 at 10:34 AM, Rony G. Flatscher
>>>>>> <rony.flatsc...@wu.ac.at
>>>>>> <mailto:rony.flatsc...@wu.ac.at>> wrote:
>>>>>>
>>>>>> Further information, using the initial e-mail to keep
>>>>>> all relevant
>>>>>> information in one e-mail.
>>>>>>
>>>>>> Today I uninstalled the 32-bit ooRexx 5.0beta and
>>>>>> installed the 64-bit ooRexx
>>>>>> 5.0beta (both from SourceForge, downloaded February 4th
>>>>>> 2017).
>>>>>>
>>>>>> This time the program ran successfully to the end:
>>>>>>
>>>>>> * there were more than 247,000 XML elements processed
>>>>>> o as already mentioned this may translate into
>>>>>> million(s) call backs
>>>>>> from Java to Rexx as all SAX events will cause
>>>>>> callbacks to Rexx
>>>>>> + some of these callbacks carry Java objects
>>>>>> as arguments which
>>>>>> will get wrapped as a peer ooRexx object
>>>>>> (ultimately an instance
>>>>>> of the class .BSF that has an uninit method
>>>>>> defined), namely the
>>>>>> Java types: "char[]", "Attributes", "Local"
>>>>>> from the callbacks
>>>>>>
>>>>>> <https://docs.oracle.com/javase/7/docs/api/org/xml/sax/ContentHandler.html
>>>>>>
>>>>>> <https://docs.oracle.com/javase/7/docs/api/org/xml/sax/ContentHandler.html>>
>>>>>> + there are no return values (all callbacks
>>>>>> are defined to be void)
>>>>>>
>>>>>> * it took a total of 2:37 hours to SAX-parse a 10MB
>>>>>> XML file,
>>>>>> o the SAX-parsing was over after 1:45 hours
>>>>>> + the program constantly slowed down and in
>>>>>> between paused for a
>>>>>> while (which got longer and longer over time)
>>>>>> o after the SAX-parseing was over the Rexx program
>>>>>> needed another 0:52
>>>>>> hours to complete
>>>>>> + speculating/assuming that in this time all
>>>>>> the uninits got
>>>>>> executed (which is fine)
>>>>>>
>>>>>> * it consumed 8.7GB of memory
>>>>>> o ProcessExplorer reports a
>>>>>> + Physical Memory "PeekWorking Set" of
>>>>>> 8.795.796 K
>>>>>> + Virtual Memory "Virtual Size" of 13.404.424
>>>>>> K with "Peak Private
>>>>>> Bytes" of 9.138.664 K
>>>>>>
>>>>>> * it used 24% of the CPU over all 2:37 hours
>>>>>> o ProcessExplorer reports a
>>>>>> + "Kernel Time" of 0:01:10.184
>>>>>> + "User Time" of 2.32.57.960
>>>>>> + "Total Time" of 2:34:08.144
>>>>>> + "Cycles": 23.898.290.997.693
>>>>>>
>>>>>> Will check the BSF4ooRexx call and code paths.
>>>>>>
>>>>>> ---rony
>>>>>>
>>>>>>
>>>>>>
>>>>>> On 26.04.2017 20:28, Rony G. Flatscher wrote:
>>>>>>>
>>>>>>> A student is using BSF4ooRexx to parse a huge XML file
>>>>>>> using Java's SAX parser.
>>>>>>>
>>>>>>> The SAX (simple API for XML) works with a callback
>>>>>>> concept. In order to be
>>>>>>> eligible for these SAX callbacks the ContentHandler
>>>>>>> interface
>>>>>>>
>>>>>>> <https://docs.oracle.com/javase/7/docs/api/org/xml/sax/ContentHandler.html>
>>>>>>>
>>>>>>> <https://docs.oracle.com/javase/7/docs/api/org/xml/sax/ContentHandler.html>
>>>>>>> must be implemented, which the Rexx program does with
>>>>>>> the help of BSF4ooRexx.
>>>>>>>
>>>>>>> As a result each single SAX event will cause an
>>>>>>> appropriate Rexx message to
>>>>>>> be generated and dispatched. The Rexx message is named
>>>>>>> after the
>>>>>>> ContentHandler method name and will receive all
>>>>>>> arguments documented there.
>>>>>>> All arguments are processed in native code, a Rexx
>>>>>>> array object will get
>>>>>>> created from the Java arguments.
>>>>>>>
>>>>>>> This works and was presented on one of the
>>>>>>> International Rexx symposiums and
>>>>>>> has become part of my lecture using Java camouflaged as
>>>>>>> ooRexx with the help
>>>>>>> of BSF4ooRexx. Here is a link to the symposium which
>>>>>>> contains links to the
>>>>>>> slides: <http://rexxla.org/events/2013/schedule.html>
>>>>>>> <http://rexxla.org/events/2013/schedule.html>.
>>>>>>>
>>>>>>> Now, a student is in the need to parse a rather huge
>>>>>>> XML file (10 MB) and
>>>>>>> uses the SAX parser. She always hits the Rexx "Error 5:
>>>>>>> System resources
>>>>>>> exhausted"! I asked her to come up with a very small
>>>>>>> program to demonstrate
>>>>>>> the error and I am able to reproduce it reliably!
>>>>>>>
>>>>>>> Here is the rather short Rexx program:
>>>>>>> --- #!/usr/bin/rexx parse arg xmlFile if xmlFile="" then
>>>>>>> XMLFile="..\LB-HB.onlb" if
>>>>>>> sysFileExists(xmlFile)=.false then do say "File"
>>>>>>> pp(xmlFile) "does not exist, aborting." exit -1 end
>>>>>>> rexxObject=.saxHandler~new();
>>>>>>>
>>>>>>> javaProxy=BSFCreateRexxProxy(rexxObject,,"org.xml.sax.ContentHandler")
>>>>>>>
>>>>>>> parser=bsf.loadClass("org.xml.sax.helpers.XMLReaderFactory")~createXMLReader
>>>>>>> parser~setContentHandler(javaProxy) eh=.errorHandler~new
>>>>>>>
>>>>>>> javaEH=BsfCreateRexxProxy(eh,,"org.xml.sax.ErrorHandler")
>>>>>>> parser~setErrorHandler(javaEH) signal on syntax
>>>>>>> start=.dateTime~new say
>>>>>>> pp(start)": start of parsing" parser~parse(XMLFile)
>>>>>>> end=.dateTime~new say
>>>>>>> pp(end)": end of parsing" say "done, needed:"
>>>>>>> pp(end-start) exit syntax: say
>>>>>>> "error at" rexxObject~nrOfElements "element"
>>>>>>> co=condition('o') say
>>>>>>> ppCondition2(co) ::requires "BSF.CLS" /* get the Java
>>>>>>> support */ ::requires
>>>>>>> "rgf_util2.rex" ::CLASS "SaxHandler" -- a Rexx content
>>>>>>> handler
>>>>>>> ("org.xml.sax.ContentHandler") ::attribute nrOfElements
>>>>>>> ::METHOD init
>>>>>>> --ooRexx constructor expose nrOfElements nrOfElements=0
>>>>>>> ::METHOD
>>>>>>> startElement expose nrOfElements USE ARG uri,
>>>>>>> localName, qName, attributes
>>>>>>> nrOfElements+=1 if nrOfElements//1000=0 then say
>>>>>>> nrOfElements "elements so
>>>>>>> far ..." ::METHOD characters -- the callback method for
>>>>>>> characters (text)
>>>>>>> USE ARG charArray, start, length ::METHOD endElement
>>>>>>> USE ARG uri, localName,
>>>>>>> qName, attributes ::method unknown ::class ErrorHandler
>>>>>>> ::method unknown use
>>>>>>> arg methName, argArray exception=argArray[1]s
>>>>>>> .error~say(methName": "
>>>>>>> "line="exception~getLineNumber
>>>>>>> ",col="exception~getColumnNumber": "
>>>>>>> pp(exception~getMessage)) ---
>>>>>>> As you might see, there is nothing "special" going on
>>>>>>> here, other than being
>>>>>>> able to supply a Rexx object as the callback object for
>>>>>>> the Java implemented
>>>>>>> SAX parser! It seems that running all these callback
>>>>>>> from Java to Rexx will
>>>>>>> cause eventually that ooRexx gets exhausted of system
>>>>>>> resources. While
>>>>>>> running the program it can be observed that from time
>>>>>>> to time there are
>>>>>>> little lags as if some garbage collecting takes place.
>>>>>>> Eventually the error
>>>>>>> 5 is thrown, while executing in native code:
>>>>>>>
>>>>>>> result_obj=rtc->SendMessage(ro, c_msg, ra); // with
>>>>>>> arguments
>>>>>>>
>>>>>>> Please note that the following error message only gives
>>>>>>> the numbers of XML
>>>>>>> elements that the SAX parser reported. In reality,
>>>>>>> *all* callbacks are
>>>>>>> carried out from Java to Rexx, the unprocessed ones
>>>>>>> will be intercepted by
>>>>>>> the Rexx UNKNOWN method. So there is a flurry of
>>>>>>> context switches and
>>>>>>> creation of Rexx array objects for the arguments and
>>>>>>> the like. Here is the
>>>>>>> error message on my system.
>>>>>>> --- 83000 elements so far ... 84000 elements so far ...
>>>>>>> error at 84926
>>>>>>> element [ADDITIONAL] =[an Array (2 items)
>>>>>>> id#_-1457160369]
>>>>>>> ["BSF4ooRexx/routine/BSF(), error 3: Java exception
>>>>>>> occurred:
>>>>>>> [org.rexxla.bsf.engines.rexx.RexxException:
>>>>>>> BSF4ooRexx/routine/jniRexxSendMessageToRexxObject(),
>>>>>>> error 4:" || "0A"x || "
>>>>>>> *-* Compiled method ""OBJECTNAME="" with scope
>>>>>>> ""Object""." || "0A"x ||
>>>>>>> "Error 5 running C:\Program Files
>>>>>>> (x86)\BSF4ooRexx\BSF.CLS line 2644: System
>>>>>>> resources exhausted." || "0A"x || "Error 5.0: message
>>>>>>> n/a]"]
>>>>>>> [org.rexxla.bsf.engines.rexx.RexxException@182d820
>>>>>>> id#_-1478994985] [CODE]
>>>>>>> =[40.900] [CONDITION] =[SYNTAX] [DESCRIPTION]=[]
>>>>>>> [ERRORTEXT] =[Incorrect
>>>>>>> call to routine.] [INSTRUCTION]=[SIGNAL] [MESSAGE]
>>>>>>> =["BSF4ooRexx/routine/BSF(), error 3: Java exception
>>>>>>> occurred:
>>>>>>> [org.rexxla.bsf.engines.rexx.RexxException:
>>>>>>> BSF4ooRexx/routine/jniRexxSendMessageToRexxObject(),
>>>>>>> error 4:" || "0A"x || "
>>>>>>> *-* Compiled method ""OBJECTNAME="" with scope
>>>>>>> ""Object""." || "0A"x ||
>>>>>>> "Error 5 running C:\Program Files
>>>>>>> (x86)\BSF4ooRexx\BSF.CLS line 2644: System
>>>>>>> resources exhausted." || "0A"x || "Error 5.0: message
>>>>>>> n/a]."] [PACKAGE] =[a
>>>>>>> Package id#_-2109388833] [POSITION] =[25] [PROGRAM]
>>>>>>> =[F:\tmp\orx\kirisits\20170425\SAX_noAlerts.rxj]
>>>>>>> [PROPAGATED] =[1] [RC]
>>>>>>> =[40] [STACKFRAMES]=[a List (4 items) id#_-1467321073]
>>>>>>> [ *-* Compiled
>>>>>>> routine "BSF". id#_-1939043649] [ 1811 *-* res=BSF(
>>>>>>> "invoke",
>>>>>>> "com.sun.org.apache.xerces.int
>>>>>>>
>>>>>>> <http://com.sun.org.apache.xerces.int>ernal.parsers.SAXParser@117ae12",
>>>>>>> "PARSE" , a.1 ) id#_-1938526417] [ 1813 *-* interpret
>>>>>>> code ")" -- execute
>>>>>>> this dynamically created Rexx string id#_-1937397361] [
>>>>>>> 25 *-*
>>>>>>> parser~parse(XMLFile) id#_-1936143753] [TRACEBACK] =[a
>>>>>>> List (4 items)
>>>>>>> id#_-1458379065] [ *-* Compiled routine "BSF".] [ 1811
>>>>>>> *-* res=BSF(
>>>>>>> "invoke", "com.sun.org.apache.xerces.int
>>>>>>>
>>>>>>> <http://com.sun.org.apache.xerces.int>ernal.parsers.SAXParser@117ae12",
>>>>>>> "PARSE" , a.1 )] [ 1813 *-* interpret code ")" --
>>>>>>> execute this dynamically
>>>>>>> created Rexx string] [ 25 *-* parser~parse(XMLFile)] ---
>>>>>>> The traceback points to the invocation of the SAX
>>>>>>> parser from Rexx which
>>>>>>> only returns upon completion of the Java parse method,
>>>>>>> or in this case when
>>>>>>> an error interrupts the program. --- So now my
>>>>>>> question/request: how to
>>>>>>> debug this problem/error? How can I get more
>>>>>>> information from the ooRexx
>>>>>>> interpreter? How can one determine what kind of "system
>>>>>>> resources" got
>>>>>>> exhausted and what the cause would be? Can one e.g.
>>>>>>> determine how many Rexx
>>>>>>> objects there are and how many are dead, in the need of
>>>>>>> getting garbage
>>>>>>> collected? In this case whenever (on each SAX callback)
>>>>>>> the Java side
>>>>>>> invokes the native code which then sends the message to
>>>>>>> the Rexx object
>>>>>>> there will be an AttachThread() followed by a
>>>>>>> DetachThread(). Please advise!
>>>>>>> ---rony
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Oorexx-devel mailing list
Oorexx-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/oorexx-devel
