ADSM-L

Need help deciphering client trace info

2000-02-14 13:09:18
Subject: Need help deciphering client trace info
From: Barbara Andrews <BAndrews AT ERIE1.WNYRIC DOT ORG>
Date: Mon, 14 Feb 2000 13:09:18 -0500
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 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
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
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 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
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
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
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.
<Prev in Thread] Current Thread [Next in Thread>