Hmmm,
Based on the endtxn verb I'm thinking your server database cache hit rate
might be a bit low. Take a look at it.
tsm> q db f=d
if the cache hit rate is below 98%, consider increasing the buffpoolsize on
your server. You will need to do this by updating the server option and
restarting the server.
Laura G. Buckley
Storage Solutions Specialists, Inc.
PO Box 51313
Colorado Springs CO 80949-1313
(719)531-5133, FAX (719)260-5991
buckley AT storsol DOT com
www.storsol.com
> >>>-----Original Message-----
> >>>From: ADSM: Dist Stor Manager
> >>>[mailto:ADSM-L AT VM.MARIST DOT EDU]On Behalf Of
> >>>Barbara Andrews
> >>>Sent: Monday, February 14, 2000 11:09 AM
> >>>To: ADSM-L AT VM.MARIST DOT EDU
> >>>Subject: Need help deciphering client trace info
> >>>
> >>>
> >>>I've been trying to get one of our Novell 4.1.1 clients
> >>>ADSM client level
> >>>3.1.0.7) to get thru an incremental backup of all data in
> >>>a reasonable
> >>>amount of time. It had been taking around 24 hrs. To
> >>>determine where the
> >>>problem is, I ran backups of subsets of data, then took
> >>>the longest running
> >>>subset and ran backups both incrementally and selectively
> >>>to see if there
> >>>was a difference. And WOW, was there. I posted a
> >>>question here several
> >>>weeks ago asking for ideas why this might be. One
> >>>suggestion I received
> >>>was to turn on client tracing using "traceflags
> >>>instr_client_detail" to
> >>>help further determine the problem. I did this, but I
> >>>don't see in the
> >>>ADSM Trace Facility Guide how to interpret the resulting
> >>>trace info. Any
> >>>help would be appreciated. Here is both the activity log
> >>>and trace info
> >>>for both the selective and incremental runs:
> >>>
> >>>Activity log for selective run:
> >>>
> >>>02/11/2000 19:57:28 --- SCHEDULEREC QUERY BEGIN
> >>>02/11/2000 19:57:28 --- SCHEDULEREC QUERY END
> >>>02/11/2000 19:57:28 Next operation scheduled:
> >>>02/11/2000 19:57:28
> >>>------------------------------------------------------------
> >>>02/11/2000 19:57:28 Schedule Name: E011ERIE1-ALL
> >>>02/11/2000 19:57:28 Action: Selective
> >>>02/11/2000 19:57:28 Objects: vol1:users/ -subdir=yes
> >>>02/11/2000 19:57:28 Options:
> >>>02/11/2000 19:57:28 Server Window Start: 20:00:00 on 02/11/2000
> >>>02/11/2000 19:57:28
> >>>------------------------------------------------------------
> >>>02/11/2000 20:56:07 Selective Backup processing of
> >>>'VOL1:USERS/' finished
> >>>without failure.
> >>>
> >>>02/11/2000 20:56:08 --- SCHEDULEREC OBJECT END
> >>>E011ERIE1-ALL 02/11/2000
> >>>20:00:00
> >>>02/11/2000 20:56:08 --- SCHEDULEREC STATUS BEGIN
> >>>E011ERIE1-ALL 02/11/2000
> >>>20:00:00
> >>>02/11/2000 20:56:08 Total number of objects inspected: 27,706
> >>>02/11/2000 20:56:08 Total number of objects backed up: 27,700
> >>>02/11/2000 20:56:08 Total number of objects updated: 0
> >>>02/11/2000 20:56:08 Total number of objects rebound: 0
> >>>02/11/2000 20:56:08 Total number of objects deleted: 0
> >>>02/11/2000 20:56:08 Total number of objects failed: 0
> >>>02/11/2000 20:56:08 Total number of bytes transferred: 1.32 GB
> >>>02/11/2000 20:56:08 Data transfer time: 2,421.95 sec
> >>>02/11/2000 20:56:08 Network data transfer rate:
> >>>573.98 KB/sec
> >>>02/11/2000 20:56:08 Aggregate data transfer rate:
> >>>395.28 KB/sec
> >>>02/11/2000 20:56:08 Objects compressed by: 0%
> >>>02/11/2000 20:56:08 Elapsed processing time: 00:58:36
> >>>02/11/2000 20:56:08 --- SCHEDULEREC STATUS END
> >>>E011ERIE1-ALL 02/11/2000
> >>>20:00:00
> >>>02/11/2000 20:56:08 Scheduled event 'E011ERIE1-ALL'
> >>>completed successfully.
> >>>02/11/2000 20:56:08 Sending results for scheduled event
> >>>'E011ERIE1-ALL'.
> >>>02/11/2000 20:56:08 Results sent to server for scheduled event
> >>>'E011ERIE1-ALL'.
> >>>
> >>>Trace info for selective run:
> >>>
> >>>Final Detailed Instrumentation statistics
> >>>
> >>>Elapsed time: 3521.280 sec
> >>>
> >>>Section Total Time(sec) Average Time(msec) Frequency used
> >>>
> >>>------------------------------------------------------------------
> >>>Client Setup 1.480 1480.0 1
> >>>Process Dirs 46.340 21.4 2168
> >>>Solve Tree 17.200 17200.0 1
> >>>Compute 1.610 0.0 66609
> >>>Transaction 193.150 0.8 229993
> >>>BeginTxn Verb 0.000 0.0 134
> >>>File I/O 326.600 3.5 94309
> >>>Compression 0.000 0.0 0
> >>>Data Verb 2421.550 36.4 66609
> >>>Confirm Verb 5.370 179.0 30
> >>>EndTxn Verb 503.470 3757.2 134
> >>>Client Cleanup 4.510 4510.0 1
> >>>
> >>>------------------------------------------------------------------
> >>>
> >>>***********************************************************
> >>>****************************************************
> >>>
> >>>Activity log for incremental run:
> >>>
> >>>
> >>>02/13/2000 16:57:25 --- SCHEDULEREC OBJECT BEGIN
> >>>DIANE-TEST 02/13/2000
> >>>17:00:0002/13/2000 16:57:25 --- SCHEDULEREC QUERY BEGIN
> >>>02/13/2000 16:57:25 --- SCHEDULEREC QUERY END
> >>>02/13/2000 16:57:25 Next operation scheduled:
> >>>02/13/2000 16:57:25
> >>>------------------------------------------------------------
> >>>02/13/2000 16:57:25 Schedule Name: DIANE-TEST
> >>>02/13/2000 16:57:25 Action: Incremental
> >>>02/13/2000 16:57:25 Objects: vol1:users/ -subdir=yes
> >>>02/13/2000 16:57:25 Options:
> >>>02/13/2000 16:57:25 Server Window Start: 17:00:00 on 02/13/2000
> >>>02/13/2000 16:57:25
> >>>------------------------------------------------------------
> >>>02/13/2000 16:57:25
> >>>Executing scheduled command now.
> >>>02/13/2000 16:57:25 --- SCHEDULEREC OBJECT BEGIN DIANE-TEST
> >>>
> >>>
> >>>
> >>>02/14/2000 01:06:06 Total number of objects inspected: 27,712
> >>>02/14/2000 01:06:06 Total number of objects backed up: 5
> >>>02/14/2000 01:06:06 Total number of objects updated: 0
> >>>02/14/2000 01:06:06 Total number of objects rebound: 0
> >>>02/14/2000 01:06:06 Total number of objects deleted: 13
> >>>02/14/2000 01:06:06 Total number of objects failed: 0
> >>>02/14/2000 01:06:06 Total number of bytes transferred: 86.45 KB
> >>>02/14/2000 01:06:06 Data transfer time: 0.05 sec
> >>>02/14/2000 01:06:06 Network data transfer rate:
> >>>1,729.08 KB/sec
> >>>02/14/2000 01:06:06 Aggregate data transfer rate:
> >>>0.00 KB/sec
> >>>02/14/2000 01:06:06 Objects compressed by: 0%
> >>>02/14/2000 01:06:06 Elapsed processing time: 08:08:41
> >>>02/14/2000 01:06:06 --- SCHEDULEREC STATUS END DIANE-TEST
> >>>02/13/2000
> >>>Trace info for incremental run:
> >>>
> >>>Final Detailed Instrumentation statistics
> >>>
> >>>Elapsed time: 29325.810 sec
> >>>
> >>>Section Total Time(sec) Average Time(msec) Frequency used
> >>>
> >>>------------------------------------------------------------------
> >>>Client Setup 0.280 280.0 1
> >>>Process Dirs 72.960 33.6 2169
> >>>Solve Tree 0.270 270.0 1
> >>>Compute 0.000 0.0 5
> >>>Transaction 29249.560 13349.9 2191
> >>>BeginTxn Verb 0.000 0.0 1
> >>>File I/O 0.160 16.0 10
> >>>Compression 0.000 0.0 0
> >>>Data Verb 0.050 10.0 5
> >>>Confirm Verb 0.000 0.0 0
> >>>EndTxn Verb 0.440 440.0 1
> >>>Client Cleanup 4.510 4510.0 1
> >>>
> >>>------------------------------------------------------------------
> >>>
> >>>Obviously the transaction time for the incremental run is
> >>>huge. Can anyone
> >>>tell me what this time accounts for? Any other observations or
> >>>suggestions? TIA.
> >>>
|
