ARSLOAD extreme slow

[teeraw]

Dear all,

I have problem on ARSLOAD command in CMOD 7.1.2.x on HP/UX.
When we load text file around 800K into CMOD, it will take time around 1-2 Minutes to completed.
How can we tuning something to improve loading performance?

I have scheduled to runstats for all tables in CMOD as daily basis.

[Alessandro Perucchi]

Hi,

Simple and at the same time, difficult question!!!!!!!!!!!!!!!!

Your problem is a generic one, or it is a problem that happens only now, since a few days?
Does your environment has enough memory, cpu, disk space?
What kind of indexer do you use? Generic Indexer? ACIF? PDF Indexer?
Do you use TSM? If you use TSM, does the file is stored directly to TSM, or does it go to the cache first, and after a migration it goes to TSM?
If you use TSM with a direct storage to TSM (without the cache "staging area"), do you write directly to TSM disk, or directly to tapes/WORM?
...

[teeraw]

Hi,

Simple and at the same time, difficult question!!!!!!!!!!!!!!!!

Your problem is a generic one, or it is a problem that happens only now, since a few days?
Does your environment has enough memory, cpu, disk space?
What kind of indexer do you use? Generic Indexer? ACIF? PDF Indexer?
Do you use TSM? If you use TSM, does the file is stored directly to TSM, or does it go to the cache first, and after a migration it goes to TSM?
If you use TSM with a direct storage to TSM (without the cache "staging area"), do you write directly to TSM disk, or directly to tapes/WORM?
...

Hi Alessandro,

I used indexer as ACIF
My environment is no TSM integrated (Cache only)

I checked that If I copied problem application group to new one, loading time will better than old one.
But not good idea, if I will duplicate every problem appgroups to new one, because my environment has around 500 appgroups.

If not sure is it related to number of files in each appgroups. (Problem was occured on appgroups those split to multiple segment table)

Thanks.

[ewirtz]

Hi,

if you use the acif indexer you can see where the time is left:

arsload: 10/25/15 06:30:27 -- Indexing started, 7781 bytes to process
.
.
arsload: 10/25/15 06:30:27 Indexing completed

arsload: 10/25/15 06:30:27 -- Loading started,
.
.
arsload: 10/25/15 06:30:31 Loading completed

In this example the most time is used for the load not for DB2

regards

Egon

[teeraw]

Hi,

if you use the acif indexer you can see where the time is left:

arsload: 10/25/15 06:30:27 -- Indexing started, 7781 bytes to process
.
.
arsload: 10/25/15 06:30:27 Indexing completed

arsload: 10/25/15 06:30:27 -- Loading started,
.
.
arsload: 10/25/15 06:30:31 Loading completed

In this example the most time is used for the load not for DB2

regards

Egon

Hi ewirtz,

I have some strange point the system log show that same file load around 10 sec. (Both indexing and loading steps finished in 10sec.)
But gap time between eache files to be loaded will be around 1-2 minutes. (I have check my loading script no step that consume time between each file)

It seems time in system log for msg.87 is not matched to actual time.

[Alessandro Perucchi]

I have a small question... is there always such slowness, or is it something quite new?
If I remember correctly with CMOD 8.3, there is a way to tell arsload to write more trace info.
Right now I don't remember the correct parameter... maybe -1 and -2 like today.

[teeraw]

I have a small question... is there always such slowness, or is it something quite new?
If I remember correctly with CMOD 8.3, there is a way to tell arsload to write more trace info.
Right now I don't remember the correct parameter... maybe -1 and -2 like today.

Hi Alessandro,

I just found -L option but when I used -L 15, it seems no trace log has been generated.

Thanks.

[Justin Derrick]

Just paste in your arsload output so we can see for ourselves how long this is taking, and if we see any big issues with your indexing parameters.

-JD.

[Maciej Mieczakowski]

I faced once an issue with quite slow loading for scenario where data have been loaded from multiple loading directories at once (we had over 20 loading daemons each was loading data to different APPGR, CMOD server 8.5.0.6). We had also a big consumption of CPU, kernell usage was oscillating around 40%, so we had a real problem...

When 1 loading daemon was processing it was taking less then 1s to process data and sent to TSM/cache/db, but when 20 daemons  were loading it was taking around 30s per each file!

After a long time spent with IBM on call, we found out interesting issue, that was not mentioned at all in product documentation (a tech note should be added, I don't know if it was).

We couldn't find any documented information about specifically setting GSKit libraries in the LIBPATH. I had issues with gsk links in /usr/lib  (run /usr/lib/libgsk* , my result was:

exec(): 0509-036 Cannot load program /usr/lib/libgsk7acmeidup.so because of the following errors:
        0509-151 The program does not have an entry point or
                   the o_snentry field in the auxiliary header is invalid.
        0509-194 Examine file headers with the 'dump -ohv' command.

We couldn't find a reason of it, but we found out that when you set LIBPATH parameter and add exact location of your GSKIT directory it start working correctly I assume it was due to GSKIT location. We guess the software assume that the /usr/lib is set in LIBPATH by default

For me it solved the issue, now it takes around 1s instead of 30s to process data from 20 loading directories in parallel. I'm not sure how it is in 9.5 now. Will test that pretty soon But maybe it's worth trying, of course after you do some more research

[Alessandro Perucchi]

Hi Maciej,

I've though about GSK problem, but since he is with CMOD V8.3, GSK is not an issue, since it wasn't a pre-req for CMOD at that time and version...

But your comment is clearly interesting for CMOD V8.5+. Concerning CMOD V9.5, I've seen no slowdown due to GSKit

Kind regards,
Alessandro

[Justin Derrick]

Further to Maciej's point, the new hashing method for storing passwords had an effect on load speed performance in 8.5.  This was resolved in v9.0 by using stash files, and further improved in v9.5 by combining a lot of the functions of arsadmin into arsload.

-JD.

[teeraw]

Just paste in your arsload output so we can see for ourselves how long this is taking, and if we see any big issues with your indexing parameters.

-JD.

Hi JD and All,

After I have enabled trace on arsload, trace output like this:

4667     3237     1        11/07/15 13:05:46.449293 ENTER  ArcLOAD_GetNextParmsLine
4667     3237     1        11/07/15 13:05:46.449719 RETURN ArcLOAD_GetNextParmsLine
4667     3237     1        11/07/15 13:05:46.468771 ENTER  ArcLOAD_GetNextParmsLine
4667     3237     1        11/07/15 13:05:46.469167 RETURN ArcLOAD_GetNextParmsLine
4667     3237     1        11/07/15 13:05:46.480976 RETURN ArcLOAD_ParseParmsFile RC=RC=0
4667     3237     1        11/07/15 13:05:46.481444 ENTER  ArcLOAD_Run
4667     3237     1        11/07/15 13:05:46.587314 RETURN ArcLOAD_Run RC=RC=0
4667     3237     1        11/07/15 13:05:46.587826 ENTER  ArcLOAD_ReadFile
4667     3237     1        11/07/15 13:05:46.588293 RETURN ArcLOAD_ReadFile
4667     3237     1        11/07/15 13:05:46.594638 RETURN ArcLOAD_IndexFile RC=RC=0
4667     3237     1        11/07/15 13:05:46.595078 ENTER  ArcLOAD_LoadFile
4667     3237     1        11/07/15 13:05:46.608939 ENTER  ArcLOAD_Run
4667     3237     1        11/07/15 13:05:50.142088 RETURN ArcLOAD_Run RC=RC=0
4667     3237     1        11/07/15 13:05:50.142638 ENTER  ArcLOAD_ReadFile
4667     3237     1        11/07/15 13:05:50.143165 RETURN ArcLOAD_ReadFile
4667     3237     1        11/07/15 13:05:50.155497 RETURN ArcLOAD_LoadFile RC=RC=0
4667     3237     1        11/07/15 13:05:50.155976 ENTER  ArcLOAD_Run
4667     3237     1        11/07/15 13:07:02.412864 RETURN ArcLOAD_Run RC=RC=0
4667     3237     1        11/07/15 13:07:02.413426 ENTER  ArcLOAD_ReadFile
4667     3237     1        11/07/15 13:07:02.413919 RETURN ArcLOAD_ReadFile
4667     3237     1        11/07/15 13:07:02.427007 RETURN ArcLOAD_ProcessFile RC=RC=0
4667     3237     1        11/07/15 13:07:02.427422 RETURN ArcLOAD_Main RC=RC=0
4667     3237     1        11/07/15 13:07:02.441411 INFO   ArcTRACE_Term Trace function terminated

It seem has step that used around 2 minutes to finish but I still not understand it.
Can you known what is it do on this step?

[Justin Derrick]

I was actually looking for the arsload output, not the trace file output.

-JD.

[teeraw]

I was actually looking for the arsload output, not the trace file output.

-JD.

Hi JD,

Please find below (There is different timestamp between arsload output and arsload trace in loading same file)
arsload: Processing file >/arsmanage/REPORT/arsload/NGTB3151106022.TXT<
arsload: 11/07/15 13:05:46 -- Indexing started, 22574 bytes to process
0425-415 CC=NO
0425-415 CCTYPE=Z
0425-415 CONVERT=NO
0425-415 CPGID=874
0425-415 MCF2REF=CPCS
0425-415 LINECNT=66
0425-415 TRC=NO
0425-415 FILEFORMAT=STREAM,(NEWLINE=X'0A')
0425-415 TRIGGER1=*,1,X'5354',(TYPE=GROUP)
0425-415 TRIGGER2=0,*,X'532054204F2043204B',(TYPE=GROUP)
0425-415 FIELD1=0,0,37,(TRIGGER=2,BASE=TRIGGER)
0425-415 FIELD2=0,77,5,(TRIGGER=1,BASE=0)
0425-415 FIELD3=0,107,11,(TRIGGER=1,BASE=0)
0425-415 INDEX1=X'72705F6E616D65',FIELD1,(TYPE=GROUP,BREAK=YES)
0425-415 INDEX2=X'73746F7265',FIELD2,(TYPE=GROUP,BREAK=YES)
0425-415 INDEX3=X'72705F64617465',FIELD3,(TYPE=GROUP,BREAK=YES)
0425-415 DCFPAGENAMES=NO
0425-415 UNIQUEBNGS=YES
0425-415 IMAGEOUT=ASIS
0425-415 INDEXOBJ=GROUP
0425-415 INDEXSTARTBY=1
0425-415 INSERTIMM=NO
0425-415 RESTYPE=NONE
0425-415 inputdd=/arsmanage/REPORT/arsload/NGTB3151106022.TXT
0425-415 outputdd=/dev/null
0425-415 indexdd=/arsmanage/indexpath/NGTB3151106022.TXT.ind
0425-415 resobjdd=/dev/null
0425-440 ACIF AT PK20037 HAS COMPLETED NORMALLY WITH RETURN CODE 0.
arsload: 11/07/15 13:05:46 Indexing completed
arsload: 11/07/15 13:05:46 -- Loading started, 22574 bytes to process
OnDemand Load Id = >5997-1-0-199843FAA-16746-16746<
Loaded 1 rows into the database
Document compression type used - OD77.  Bytes Stored = >2514< Rows = >1<
arsload: 11/07/15 13:05:50 Loading completed
arsload: Processing successful for file >/arsmanage/REPORT/arsload/NGTB3151106022.TXT<

===
4667     3237     1        11/07/15 13:05:46.608939 ENTER  ArcLOAD_Run
4667     3237     1        11/07/15 13:05:50.142088 RETURN ArcLOAD_Run RC=RC=0
4667     3237     1        11/07/15 13:05:50.142638 ENTER  ArcLOAD_ReadFile
4667     3237     1        11/07/15 13:05:50.143165 RETURN ArcLOAD_ReadFile
4667     3237     1        11/07/15 13:05:50.155497 RETURN ArcLOAD_LoadFile RC=RC=0
4667     3237     1        11/07/15 13:05:50.155976 ENTER  ArcLOAD_Run
4667     3237     1        11/07/15 13:07:02.412864 RETURN ArcLOAD_Run RC=RC=0
4667     3237     1        11/07/15 13:07:02.413426 ENTER  ArcLOAD_ReadFile
4667     3237     1        11/07/15 13:07:02.413919 RETURN ArcLOAD_ReadFile
4667     3237     1        11/07/15 13:07:02.427007 RETURN ArcLOAD_ProcessFile RC=RC=0
4667     3237     1        11/07/15 13:07:02.427422 RETURN ArcLOAD_Main RC=RC=0

[Justin Derrick]

Okay, that's truly bizarre.  It's taking almost a full minute to return to CMOD after the load says it's complete.

I'm going to throw out a guess, and suggest that it's related to DB2.  The only step left after a successful completion of a load is to write messages to the System Log.  It seems like there's a 60+ second timeout happening somewhere.  Check the db2diag log for errors/messages happening around the time of this load.

Given that you're on a drastically unsupported version of CMOD, you're not likely to get much help from IBM.

It's been two weeks since this thread was started -- are you still having the issue?

-JD.