Heap growth during runLocally()and production run time debug

Post questions here relative to DataStage Enterprise/PX Edition for such areas as Parallel job design, Parallel datasets, BuildOps, Wrappers, etc.

Moderators: chulett, rschirm, roy

Post Reply
Developer9
Premium Member
Premium Member
Posts: 187
Joined: Thu Apr 14, 2011 5:10 pm

Heap growth during runLocally()and production run time debug

Post by Developer9 »

Hi,
I am debugging one of the job running in single node (DS 11.5 / windows server) that is taking "about 5 minutes of production run time " .my goal is to identify bottlenecks and performance tuning of job to make sure it runs efficiently (lesser time).

Job design contains reading oracle source data (connector stages-record range 0.1M to 4M), datasets (record range 500 to 100000) being used as reference data for join,lookup operations also several other stages sort ,copy,aggregator ,funnel and transformer stages ..target its writing to 2 data sets .(overall 50 and above stages)



Transformer LOGIC

Code: Select all

**timestamp to varchar conversion ***
If IsNull(DATE_CREATED) Then '' Else If IsValidTimestamp(DATE_CREATED)  Then DateToString(TimestampToDate(DATE_CREATED),"%mm/%dd/%yyyy") 
Else '' 

**Decimal conversion **
DecimalToString(val,"fix_zero,suppress_zero") 
Director job logs


10:16:34 AM Starting Job ..
$APT_CONFIG_FILE = C:\IBM\InformationServer\Server\Configurations\1Node.apt
$APT_DISABLE_COMBINATION = True
$APT_SORT_INSERTION_CHECK_ONLY = False
$APT_STRING_PADCHAR = 0x0 (From value file)
$APT_PM_PLAYER_TIMING = False (From value file)
$APT_PM_PLAYER_MEMORY = True (From value file)
$APT_RECORD_COUNTS = True (From value file)
$OSH_PRINT_SCHEMAS = True (From value file)
$APT_DUMP_SCORE = True (From value file)
$APT_STARTUP_STATUS = False (User supplied)

10:16:34 AM Attached Message Handlers:
10:16:37 AM Project message handler: SortStageResort
10:16:37 AM Environment variable settings:
...
Parallel job initiated
OSH script ..
# OSH / orchestrate script for Job
main_program: orchgeneral: loaded
10:16:39 AM orchsort: loaded
10:16:39 AM orchstats: loaded
**oracle connector extract **(elapsed time =14 sec)
10:16:53 AM ext_CONTACTS_plus: The connector connected to Oracle server oradb1.

**dataset folder**
10:17:54 AM is/isdata/tgt1_ds,0: Heap growth during runLocally(): 86024192 bytes

***Transformer stage Messages (elapsed time =9 sec)
10:18:47 AM xfm_standardize,0 :Input 0 consumed 520749 records.
10:18:47 AM xfm_standardize,0: Output 0 produced 520749 records.
10:18:56 AM xfm_standardize,0: Heap growth during runLocally(): 85639168 bytes

***LOOKUP stage(elapsed time =4 sec)
10:19:06 AM lkp_ob_co_bond_obi,0: Heap growth during runLocally(): 133578752 bytes
10:19:10 AM buffer(1),0: Heap growth during runLocally(): 85590016 bytes
10:19:10 AM buffer(0),0: Heap growth during runLocally(): 85708800 bytes

***funnel stage
10:19:10 AM funl_inv_fiv,0: Heap growth during runLocally(): 85143552 bytes

***sort
10:19:11 AM srt_bond,0: Heap growth during runLocally(): 85983232 bytes
10:19:12 AMbuffer(10),0: Heap growth during runLocally(): 83468288 bytes
**oracle connector stage (elapsed time =22 sec)
10:19:12 AM ext_plus,0: Number of rows fetched on the current node: 1151731.
10:19:12 AM ext_plus,0: Output 0 produced 1151731 records.
10:19:34 AM ext_plus,0: Heap growth during runLocally(): 82477056 bytes
***copy stage **(elapsed time =1 minute ,10 sec)

10:19:38 AM cpy_stage,0: Output 0 produced 1151731 records.
10:19:38 AM cpy_stage,0: Input 0 consumed 1151731 records.
10:20:48 AM cpy_stage,0: Input 0 consumed 1151731 records.

***join stage ** (Let outer join --Input links -Auto partition )(elapsed time =1 minute ,4 sec)

10:21:33 AM Jnr_Bond_id,0: Input 0 consumed 1151731 records.
10:21:33 AM Jnr_Bond_id,0: Output 0 produced 1151731 records.
10:22:45AM Jnr_Bond_id,0: Heap growth during runLocally(): 80654336 bytes
10:22:47 AM buffer(23),0: Heap growth during runLocally(): 80687104 bytes
10:22:47 AM buffer(23),0: Heap growth during runLocally(): 80687104 bytes

***dataset ** (partition/collection --Auto )(elapsed time =6 sec)

10:22:49 AM ds_tgt1,0: Input 0 consumed 1207442 records.
10:22:49 AM ds_tgt1,0: Input 0 produced 1207442 records.
10:22:55 AM ds_tgt1,0: Heap growth during runLocally(): 79831040 bytes

10:22:55 AM main_program: Step execution finished with status = OK.
10:22:58 AM main_program: Startup time, 1:18; production run time, 4:57.
10:22:58 AM Parallel job reports successful completion
10:22:59 AM Finished Job .

Redesign :Split the original job into 1 jobs.

job1 :extract oracle data and write to 2 datasets

job2 :use 2 datasets as sources for original job ..it does n't help either rather it becomes worse.

main_program: Startup time, 0:37; production run time, 13:42.

Please give me some insights to performance tune this job.

Thanks.
chulett
Charter Member
Charter Member
Posts: 43085
Joined: Tue Nov 12, 2002 4:34 pm
Location: Denver, CO

Post by chulett »

So... let me see... you have a Parallel job with 50+ stages that processes 1 to 4 million records on a Windows server in around 5 minutes and you think the performance needs to be improved? Okay. Might be a bit difficult to whittle that down. Have you tried simply increasing the number of nodes, say to 2 as an experiment? Obviously you'd need to check your partitioning strategy if you haven't already.

I'd also be curious why the performance concern. Is this something that will be running many times over the course of the day, for example?
-craig

"You can never have too many knives" -- Logan Nine Fingers
Developer9
Premium Member
Premium Member
Posts: 187
Joined: Thu Apr 14, 2011 5:10 pm

Post by Developer9 »

@Chulett,

For the first question regarding increasing number of nodes to 2 , I attempted a test run

Code: Select all

main_program: Startup time, 1:38; production run time, 8:42.
And regarding partitioning Its a hash partition on sort stages after the oracle connector extract then down in the flow I try maintain the same with "same" partitioning every where including input to the join/lookup stages.What does heap growth insist generally ?

currently these jobs run (extract and generate delta files using change data capture ) at every 2 hour interval but the business need is to run at every 1 hour interval if possible , for that I am tuning the jobs for better timing and resource utilization stand point.

Thanks .
chulett
Charter Member
Charter Member
Posts: 43085
Joined: Tue Nov 12, 2002 4:34 pm
Location: Denver, CO

Post by chulett »

Sorry, still a bit stuck on this... it needs to run every hour and you're worried about five minute runtime? What was the worst runtime you've seen so far? I'm assuming it is being tracked.

Was worried you actually needed to run it every five minutes. Got tasked with that back in the day: take a nightly task that churned out a ton of XML in a couple of hours and cut it back so it can process "micro-batches" every five minutes. :shock: Managed to do it, though. Added a safety net that the looping Sequence job that controlled it could leverage. Track the previous runtime and if we floated past 5 minutes (gawd forbid it ran 6 minutes) it would always delay the loop until the next 5 minute clock time. Worked surprisingly well. Of course, these were all Server jobs without all of the crazy ramp up and cool down times that PX can be saddled with, but hey - made it work. <thumbsup>

Been far too long since I had any hands-on DataStage experience, so I'll let others give any specific partitioning advice they are willing to share. Unclear what the "heap growth" question is all about or how to answer it so will leave that to others as well. :wink:
-craig

"You can never have too many knives" -- Logan Nine Fingers
qt_ky
Premium Member
Premium Member
Posts: 2895
Joined: Wed Aug 03, 2011 6:16 am
Location: USA

Post by qt_ky »

If I had a 60 minute window and the job was taking only 5 to 10 minutes, then I may take a quick glance at tuning then quickly move on.

What jumps out to me is that t he job startup times look pretty bad. What in the world is going on there? Have you got some slow before-SQL statements in your database stages? Our startup times are consistently 2 to 4 seconds even on jobs with 30+ stages. There were some known issues about long startup times so it is possible you are on a version with such an issue and may need a patch. Open a support case to get help to debug it. Please let us know what you find out.

Another thing to question is the overall job design, with whatever it is doing, is it reprocessing the same records and pulling in full volumes of data with each and every run, or could it be redesigned more efficiently at every step to process only the records that are new or updated or deleted.
Choose a job you love, and you will never have to work a day in your life. - Confucius
chulett
Charter Member
Charter Member
Posts: 43085
Joined: Tue Nov 12, 2002 4:34 pm
Location: Denver, CO

Post by chulett »

https://docs.oracle.com/cd/B19306_01/se ... mns008.htm

They are a column that you generally don't need to worry about but if you want to see / use it, you need to explicitly include it.
-craig

"You can never have too many knives" -- Logan Nine Fingers
ray.wurlod
Participant
Posts: 54607
Joined: Wed Oct 23, 2002 10:52 pm
Location: Sydney, Australia
Contact:

Post by ray.wurlod »

Have you eliminated the insertion of tsort operators on both of the inputs to Join stages?

Why are you running on only one node?
IBM Software Services Group
Any contribution to this forum is my own opinion and does not necessarily reflect any position that IBM may hold.
Developer9
Premium Member
Premium Member
Posts: 187
Joined: Thu Apr 14, 2011 5:10 pm

Post by Developer9 »

For the first question ,I am using environment variable $APT_SORT_INSERTION_CHECK_ONLY = False to verify the sorted data .Does this serve the purpose to eliminate tsort operator ?
Second one,It was a suggestion by DS admin couple years ago to use only single node since then I haven't revised the configurations.Does increasing node effects on the job output ?I need to test this job with 2 node configurations in lower environment first before I make the configuration changes in production.


Job design and partition

Code: Select all

oracle connectors (inputs) --sort (hash) --join (same)--Lkp (same on stream,auto on reference) --aggregator (same) --funnel (auto) --dataset (auto)
I am considering following factors to debug the performance issue

1.Overall design (bad design may be a cause) --selecting proper partitioning
2.Remove unnecessary sorts stages from the job(currently 15-20 of them)
3.Split the single job into 2 or more jobs (more then 50 stages) ..Probably do all extracts in a single job to write it to data sets then use them in other jobs ?Does it helps ?
4.Review job log for performance related data --set these parameters
$APT_PM_PLAYER_TIMING,$APT_PM_PLAYER_MEMORY,$OSH_PRINT_SCHEMAS,$APT_DUMP_SCORE=True
5.main_program: Startup time, 0:49; production run time, 13:49...review events from director log to identify the stage/process at which point job lagged.

I have other job using change capture stage (using data sets to compare and write inserts and updates to a file) along with some other jobs also have an issue each running for more than average of 5-10 minutes so all these jobs together it is taking about a hour to complete the master sequence .So tuning is essential to reduce the timing .
Thank you for the input and suggestions
ray.wurlod
Participant
Posts: 54607
Joined: Wed Oct 23, 2002 10:52 pm
Location: Sydney, Australia
Contact:

Post by ray.wurlod »

First answer: Yes.

Second answer: Running on more than one node will increase job throughput up to linearly, assuming that the partitioning is correct. In my experience those who advise single-node operation have been too lazy to learn partitioning correctly, and the organization ends up paying huge money for an engine they're only running on a single cylinder.
IBM Software Services Group
Any contribution to this forum is my own opinion and does not necessarily reflect any position that IBM may hold.
Developer9
Premium Member
Premium Member
Posts: 187
Joined: Thu Apr 14, 2011 5:10 pm

Post by Developer9 »

@ray

I can't see the premium content at this moment .I renewed couple of days ago but still not activated yet :o

I did little testing with running same job with different nodes..so having more number of nodes always improve the performance means job run efficiently?

Code: Select all

main_program: Startup time, 5:16; production run time, 8:43 (6 node)
main_program: Startup time, 2:16; production run time, 6:12 (4 node)
main_program: Startup time, 1:28; production run time, 5:49 (2 node)
main_program: Startup time, 1:00; production run time, 5:24(1 node)
In addition environment variable added $DS_PXDEBUG = 1 to this job

Code: Select all

Oracle_Connector_plus,0: Operator completed. status: APT_StatusOk  elapsed: 141.51  user: 24.66  sys: 7.07 (total CPU: 31.73)
Transformer_Validate,1: Operator completed. status: APT_StatusOk  elapsed: 346.06  user: 15.54  sys: 2.37 (total CPU: 17.91)
Transformer_validate,3: Operator completed. status: APT_StatusOk  elapsed: 371.91  user: 7.10  sys: 0.55 (total CPU: 7.64)
What does above CPU messages implies to ?How to identify the bottlenecks from a stage or operator from director log ?

Please suggest me with your tips to debug this issue of long running job.
Thanks.
kumar_s
Charter Member
Charter Member
Posts: 5245
Joined: Thu Jun 16, 2005 11:00 pm

Post by kumar_s »

With more partition, you startup time and production time is increasing.

Are you still running with the Auto partition as you mentioned in your original job design (the first post)? Or using specific partition as you mentioned in later post?
If not done, my suggestion is to Partition the data at earlier stages in your job design. I assume your driving key for partition would be the key used to join or at the least at the same granularity. Perhaps the hash partition and maintain the same partition till the end unless you have different key based operations.

When time is all that it matters to you, as qt_ky mentioned, consider involving your admins to check on the huge startup time.

Just to make sure that the 'bottleneck' is not from the extraction, try a simple DB to Dataset extract and observer the time taken. Sometimes that may trigger adding partition in tables and to use the partition in connector stage.
Impossible doesn't mean 'it is not possible' actually means... 'NOBODY HAS DONE IT SO FAR'
Developer9
Premium Member
Premium Member
Posts: 187
Joined: Thu Apr 14, 2011 5:10 pm

Post by Developer9 »

Hi Kumar,

I am using hash partition in sort stages right after reading from DB stages .Then I am maintaining the "same"partition through out the down stream flow.

One more update regarding CPU ,upon closely monitoring the Operations console,While this job running it is reaching more than 80 % then drops suddenly after job finishes.

I am looking at the option to re-design enter jobs with these kind of issues.

Thank you
Post Reply