Problem execution time due to call to garbage Collector

One Star

Problem execution time due to call to garbage Collector

Hello,
I have a problem of execution time when I have a father job calling several children jobs (these children jobs call also children jobs ?).
I noticed this problem was mainly due to calls to System.gc(), done at the end of each job and when there is a lookup entry on tMap.
As I have several jobs and several tMap with lookup entries, I have several calls to System.gc.
If my job is launched from TOS, there is no problem but if I export my scripts into jar files and launch my job from an EJB session, each call to System.gc() takes about 300 ms and
execution time becomes very long.
I really can?t work this way and I can?t keep these calls to System.gc (I managed to comment them).
Of course, I understand there is probably a good reason to call them and I may have problems if they are suppressed.
That?s why, if somebody can explain me why they exist and, especially, why they can be so numerous,
I would be very grateful.
Thanks in advance,
Murielle
Employee

Re: Problem execution time due to call to garbage Collector

Please, can you post a piece of code around the System.gc() call?
One Star

Re: Problem execution time due to call to garbage Collector

I think it is the System.gc() call in the function reset(). I didn't make further analysis but I think it it created (and executed) for each job.
And additional I didn't think it makes sense. Or I'm wrong?
By
Volker
One Star

Re: Problem execution time due to call to garbage Collector

Hi,
System.gc() is called :
1) in method reset of each job (called at the end of each job).
This is true for any job.
2) I have a tJDBCInput component linked to a tMap. On this tMap, I also have lookup entries.
The output link of my tMap is a tJDBCOutput.
System.gc() is called at the end of method tJDBCInput_1Process, the code is :

.../...
globalMap.put("tJDBCOutput_2_NB_LINE_INSERTED",
nb_line_inserted_tJDBCOutput_2);
ok_Hash.put("tJDBCOutput_2", true);
end_Hash.put("tJDBCOutput_2", System.currentTimeMillis());
/**
* stop
*/

} catch (Exception e) {
throw new TalendException(this, e, globalMap);
}
finally {
// free memory for "tMap_1"
globalMap.put("tHash_Lookup_primaryKey", null);
// free memory for "tMap_1"
globalMap.put("tHash_Lookup_ligne_colisee_serie", null);
System.gc();
}
globalMap.put("tJDBCInput_1_SUBPROCESS_STATE", 1);
}
I could see, in talend_directory\plugins\org.talend.designer.codegen_3.0.2.r20205.jar\resources\subprocess_footer.javajet
that each time you have a tMap with at least one lookup entry, a call to System.gc() is done.
Tell me if I didn't give enough information.
Murielle
Employee

Re: Problem execution time due to call to garbage Collector

Dear user,
I'm not sure that's an anomaly but I invite you to contibute to 6174
The bugtracker is the good place to speak about technical issue about component or job.
Regards,
Olivier
One Star

Re: Problem execution time due to call to garbage Collector

Hello together,
I saw and we discussed about several impacts because of the usage of System.gc(). From my point of view there are several misunderstandings about the internals of the jvm memory handling and garbage collection. So I'll give here some general information:
First: Each implementation of the jvm (sun, ibm, ...) and version may have another behavior.
If you start a java program you could set at start time the available memory. This values are set by default from the TOS export procedure (in the .bat-file) to a minimum of 256 MB and a maximum of 1024 MB. You could set additional values or modify the existing ones under Window -> Preferences -> Talend -> Run/Debug. At the beginning the jvm will allocate the minimum value but this value is not full usable by the application. It is divided into three parts: eden space, survivor and old generation. The size of each part is calculated by the jvm, but there are many options to modify the values to resolve performance issues in special cases.
All new object are created in the new generation / eden space. If the new generation exceeds its limit a garbage collection is run. This means all objects in eden / the new generation and in the survivor spaces are checked if they are still alive (this means: are any references are hold). If yes the are copied into one survivor space (there are two with the same size). After this collection the new generation and the second survivor are empty and could hold new objects. This collection is fast and has a low cpu utilization.
In cases one survivor space couldn't hold all memory from the eden space and the second survivor, a full garbage collection occurs. This means the jvm checks the all generations, including the old generation (the larges part), for objects which aren't in use any more. The algorithm used for the full gc is better for finding unused objects but much slower. After this all objects still alived in survivor are moved to the old generation.
The idea behind this is that objects normally will have a short lifetime. So only a few objects will go to the old generation. If the old generation is full a OutOfMemoryException is raised (even if there is free memory in eden and the survivor). By the way the default behavior of the garbage collector is that it stops all processes. So any other process in the same jvm is stopped!
There are two points I actual saw (and some are already solved):
1) Usage of System.gc(): This will (in most cases) execute immediately a full gc. So never, absolutely never use System.gc()!
2) I saw some code blocks which seems to be used to evaluate the memory usage / free memory. Because of the above explained complex process they are worthless to calculate how much memory a process consumed or may be available. To get information about this you need special analysis tools.
To give you an example I created a little job (TOS 3.0.2): A main job executes in a loop 10000 times a subjob (tRunJob) which doesn't any more than writing a point to stdout. I attached a image with the details of memory management. You could see that the job needs 2 minutes and 12,695 seconds for execution. In this time 10001 full garbage collections are done which took 2 minutes and 1,933 seconds. Additional you could see that in eden there is nothing (so it took about 92 percent of the time to do: nothing).
There is some work to do by the Talend team to avoid such situations and, as I mentioned before, already done and still in progress.
But also for every user of Talend Open Studio: If you design your job and exported it and run into performance issues you should also take a look onto your runtime parameters of the jvm. Especially if you have high load, many processes which have to run in parallel or often times. This optimization should be done by professional java developers with special knowledge about java internals and performance optimization. Maybe you could wait until your servers load says: "By a new / second machine". But you are always welcome in this forum with your question.
And one last point at the end: This is not a "Talend Open Studio"-specific problem. It will affect all java systems.
Some more points I addressed in the following 5352
I hope I could clarify some points about the jvm and memory management and this information may be usefully for someone out there. :-)
Bye
Volker