performance problems with BIP–what do we do?

I’m talking about embedded BIP, that is embedded BIP in JD Edwards.  But at the end of the day, this is just BI Publisher with some handles / control from JD Edwards.  There might be some generic lessons learnt in this post.

Your JD Edwards job runs for 10 minutes and produces a load of invoices, and the BIP takes 45 minutes to deliver them!!  What makes it worse is that you cannot run concurrent BIP jobs because it falls apart, so THEN you have to guess when the BIP processing is complete before you run your next round of transformations.  Oh yes, you need to run multiple rounds of transformations because if you do them in one batch, the system falls over because it’s using too much memory and too much temp space…  AARRGGHH – when is it going to end.

What do you do first?

Probably look at https://support.oracle.com and get a bunch of recommendations about the size of the BIP JRE and a few other improvements that could occur in that area.  Look for document id 962712.1.  Sure you might get some improvements, but it’s just a stab in the dark.

You need to enable logging and look at logs.

goto the location of your xdo.cfg file in JDE.  I recommend going to $EVRHOME and doing a find . –name xdo.cfg –print to find where they might be:

[jde812@jdevap01.something.office]$ find . -name xdo.cfg -print
./system/jre/lib/xdo.cfg
./system/classes/xdo.cfg

Okay, lets get in there and create a xdodebug.cfg in the java runtime location, the top dir

[jde812@jdevap01.something.office]$ vi xdodebug.cfg
LogLevel=STATEMENT
LogDir=/tmp/xdodebug

You can see the above contents in the xdodebug.cfg

Next job that runs (yes – no restart required) will have logging on.  please we careful, there is a LOT of logging.

It leaves the temp jobs and all sorts of things in the /tmp dir – so only leave it on for the time that you need.

You’ll see files like the below:

-rw-r--r--  1 jde812 jde812   43463 Jul 17 14:45 xdo_071712_024547384_fo_out995.out
-rw-r--r--  1 jde812 jde812  110218 Jul 17 14:45 xdo_071712_024547569_fo_data_1997.xsl
-rw-r--r--  1 jde812 jde812    3937 Jul 17 14:45 xdo_071712_024547569_fo_data_1998.xml
-rw-r--r--  1 jde812 jde812    2119 Jul 17 14:45 xdo_071712_024547569_fo_fo_11000.fo
-rw-r--r--  1 jde812 jde812   43470 Jul 17 14:45 xdo_071712_024547569_fo_out999.out
-rw-r--r--  1 jde812 jde812  110218 Jul 17 14:45 xdo_071712_024547750_fo_data_11001.xsl
-rw-r--r--  1 jde812 jde812    3941 Jul 17 14:45 xdo_071712_024547750_fo_data_11002.xml
-rw-r--r--  1 jde812 jde812    2120 Jul 17 14:45 xdo_071712_024547750_fo_fo_11004.fo
-rw-r--r--  1 jde812 jde812   43465 Jul 17 14:45 xdo_071712_024547750_fo_out1003.out
-rw-r--r--  1 jde812 jde812  110218 Jul 17 14:45 xdo_071712_024547934_fo_data_11005.xsl

None of them have timestamps, so you really only want to look at xdo.log

They have fairly granular timestamping, so you can see what is taking a long time.

[071712_024602914]

For each burst job, the following is written to the logs:

[ PDF GENERATOR ]

So the gap between these tags is how log each “PDF generation took”.

[071712_091246515][][STATEMENT] [ PDF GENERATOR ]---------------------------------------------
[071712_091249539][][STATEMENT] [ PDF GENERATOR ]---------------------------------------------
[071712_091251271][][STATEMENT] [ PDF GENERATOR ]---------------------------------------------
[071712_091253486][][STATEMENT] [ PDF GENERATOR ]---------------------------------------------
[071712_091255749][][STATEMENT] [ PDF GENERATOR ]---------------------------------------------
[071712_091301647][][STATEMENT] [ PDF GENERATOR ]---------------------------------------------
[071712_091305388][][STATEMENT] [ PDF GENERATOR ]---------------------------------------------
[071712_091306836][][STATEMENT] [ PDF GENERATOR ]---------------------------------------------
[071712_091307698][][STATEMENT] [ PDF GENERATOR ]---------------------------------------------
[071712_091308514][][STATEMENT] [ PDF GENERATOR ]---------------------------------------------
[071712_091309424][][STATEMENT] [ PDF GENERATOR ]---------------------------------------------

so we can see that it’s about 2 seconds per PDF 9:12:46 to 9:13:09 23 seconds for 11 PDFs.

Email

All SMTP actions take place once all of the PDF generation occurs.  They do not send after each burst.  They do ALL bursting and then all sending.

searching the xdo.log for a string like the below, will show you how long each of the emails took:

[oracle.apps.xdo.delivery.smtp.SMTPDeliveryRequest][STATEMENT] submit(): Process done successfully. Exiting submit()

[071712_091310473][oracle.apps.xdo.delivery.smtp.SMTPDeliveryRequest][STATEMENT] submit(): Process done successfully. Exiting submit()
[071712_091310786][oracle.apps.xdo.delivery.smtp.SMTPDeliveryRequest][STATEMENT] submit(): Process done successfully. Exiting submit()
[071712_091311092][oracle.apps.xdo.delivery.smtp.SMTPDeliveryRequest][STATEMENT] submit(): Process done successfully. Exiting submit()
[071712_091311394][oracle.apps.xdo.delivery.smtp.SMTPDeliveryRequest][STATEMENT] submit(): Process done successfully. Exiting submit()
[071712_091311696][oracle.apps.xdo.delivery.smtp.SMTPDeliveryRequest][STATEMENT] submit(): Process done successfully. Exiting submit()
[071712_091312013][oracle.apps.xdo.delivery.smtp.SMTPDeliveryRequest][STATEMENT] submit(): Process done successfully. Exiting submit()
[071712_091312326][oracle.apps.xdo.delivery.smtp.SMTPDeliveryRequest][STATEMENT] submit(): Process done successfully. Exiting submit()

 

We can see from the above that it took 2 seconds to send 7 emails.

 

Memory

[071712_091251890][oracle.apps.xdo.template.FOProcessor][STATEMENT] End Memory: max=986MB, total=126MB, free=50MB
[071712_091252115][oracle.apps.xdo.template.FOProcessor][STATEMENT] Start Memory: max=986MB, total=126MB, free=35MB
[071712_091254045][oracle.apps.xdo.template.FOProcessor][STATEMENT] End Memory: max=986MB, total=125MB, free=61MB
[071712_091254193][oracle.apps.xdo.template.FOProcessor][STATEMENT] Start Memory: max=986MB, total=125MB, free=47MB
[071712_091257058][oracle.apps.xdo.template.FOProcessor][STATEMENT] End Memory: max=986MB, total=125MB, free=60MB
[071712_091257338][oracle.apps.xdo.template.FOProcessor][STATEMENT] Start Memory: max=986MB, total=125MB, free=39MB
[071712_091304392][oracle.apps.xdo.template.FOProcessor][STATEMENT] End Memory: max=986MB, total=121MB, free=20MB
[071712_091304479][oracle.apps.xdo.template.FOProcessor][STATEMENT] Start Memory: max=986MB, total=120MB, free=67MB
[071712_091306207][oracle.apps.xdo.template.FOProcessor][STATEMENT] End Memory: max=986MB, total=120MB, free=36MB
[071712_091306258][oracle.apps.xdo.template.FOProcessor][STATEMENT] Start Memory: max=986MB, total=120MB, free=28MB
[071712_091307271][oracle.apps.xdo.template.FOProcessor][STATEMENT] End Memory: max=986MB, total=113MB, free=43MB
[071712_091307296][oracle.apps.xdo.template.FOProcessor][STATEMENT] Start Memory: max=986MB, total=113MB, free=37MB
[071712_091308033][oracle.apps.xdo.template.FOProcessor][STATEMENT] End Memory: max=986MB, total=113MB, free=16MB
[071712_091308074][oracle.apps.xdo.template.FOProcessor][STATEMENT] Start Memory: max=986MB, total=115MB, free=62MB
[071712_091308869][oracle.apps.xdo.template.FOProcessor][STATEMENT] End Memory: max=986MB, total=115MB, free=40MB
[071712_091308908][oracle.apps.xdo.template.FOProcessor][STATEMENT] Start Memory: max=986MB, total=115MB, free=33MB
[071712_091309847][oracle.apps.xdo.template.FOProcessor][STATEMENT] End Memory: max=986MB, total=110MB, free=45MB

If you grep for “Memory” in the log file, you see the start and finish values for the JVM’s memory.  this might help on memory intensive jobs.

 

The actual PDFs

[jde812@jdevap01.something.office]$ cat xdo.log |grep "FOProcessor.setOutput(String)is called with" |grep 12_09
[071712_091248400][oracle.apps.xdo.template.FOProcessor][STATEMENT] FOProcessor.setOutput(String)is called with '/u03/temp/14114/071712_091246410/filehtgfqJ_EN-AU_TR5542565_001_2.pdf'.
[071712_091250524][oracle.apps.xdo.template.FOProcessor][STATEMENT] FOProcessor.setOutput(String)is called with '/u03/temp/14114/071712_091246410/filehtgfqJ_EN-AU_TR5542565_001_6.pdf'.
[071712_091252113][oracle.apps.xdo.template.FOProcessor][STATEMENT] FOProcessor.setOutput(String)is called with '/u03/temp/14114/071712_091246410/filehtgfqJ_EN-AU_TR5542565_001_9.pdf'.
[071712_091254191][oracle.apps.xdo.template.FOProcessor][STATEMENT] FOProcessor.setOutput(String)is called with '/u03/temp/14114/071712_091246410/filehtgfqJ_EN-AU_TR5542565_001_12.pdf'.
[071712_091257336][oracle.apps.xdo.template.FOProcessor][STATEMENT] FOProcessor.setOutput(String)is called with '/u03/temp/14114/071712_091246410/filehtgfqJ_EN-AU_TR5542565_001_15.pdf'.
[071712_091304470][oracle.apps.xdo.template.FOProcessor][STATEMENT] FOProcessor.setOutput(String)is called with '/u03/temp/14114/071712_091246410/filehtgfqJ_EN-AU_TR5542565_001_18.pdf'.
[071712_091306255][oracle.apps.xdo.template.FOProcessor][STATEMENT] FOProcessor.setOutput(String)is called with '/u03/temp/14114/071712_091246410/filehtgfqJ_EN-AU_TR5542565_001_21.pdf'.
[071712_091307294][oracle.apps.xdo.template.FOProcessor][STATEMENT] FOProcessor.setOutput(String)is called with '/u03/temp/14114/071712_091246410/filehtgfqJ_EN-AU_TR5542565_001_24.pdf'.
[071712_091308072][oracle.apps.xdo.template.FOProcessor][STATEMENT] FOProcessor.setOutput(String)is called with '/u03/temp/14114/071712_091246410/filehtgfqJ_EN-AU_TR5542565_001_27.pdf'.
[071712_091308906][oracle.apps.xdo.template.FOProcessor][STATEMENT] FOProcessor.setOutput(String)is called with '/u03/temp/14114/071712_091246410/filehtgfqJ_EN-AU_TR5542565_001_30.pdf'.

 

So now it’s time to drill down further to get some more performance out of this thing, any maybe some more benchmarking.