|
|
|
|
|
Level 9
|
# [ 324 ] Thu Jan 15 22:31:25 2004 559000 ( 0.000 sec) ( 123 rpc) Res: 'OK'
# [ 324 ] Thu Jan 15 22:31:25 2004 559000 ( 0.000 sec) ( 123 rpc) API> retrieve,c,dm_document
# [ 324 ] Thu Jan 15 22:31:25 2004 579000 ( 0.020 sec) ( 127 rpc) Res: '0900145280000148'
# [ 324 ] Thu Jan 15 22:31:25 2004 579000 ( 0.000 sec) ( 127 rpc) API> get,c,l,object_name
# [ 324 ] Thu Jan 15 22:31:25 2004 579000 ( 0.000 sec) ( 127 rpc) Res: 'Blank PowerPoint pre-3.0 Presentation'
# [ 324 ] Thu Jan 15 22:31:25 2004 589000 ( 0.000 sec) ( 127 rpc) API> set,c,l,object_name
# [ 324 ] Thu Jan 15 22:31:25 2004 589000 ( 0.000 sec) ( 127 rpc) SET> my new name
# [ 324 ] Thu Jan 15 22:31:25 2004 589000 ( 0.000 sec) ( 127 rpc) Res: 'OK'
# [ 324 ] Thu Jan 15 22:31:25 2004 589000 ( 0.000 sec) ( 127 rpc) API> save,c,l
# [ 324 ] Thu Jan 15 22:31:25 2004 629000 ( 0.040 sec) ( 130 rpc) Res: 'OK'
# [ 324 ] Thu Jan 15 22:31:25 2004 629000 ( 0.000 sec) ( 130 rpc) API> trace,c,0
# [ 324 ] Thu Jan 15 22:31:25 2004 629000 ( 0.000 sec) ( 131 rpc) Total Time: 0.070 sec
# [ 324 ] Thu Jan 15 22:31:25 2004 629000 ( 0.000 sec) ( 131 rpc) Total Server Requests: 131
|
|
|
The trace file for level 9 is shown above. Each line generated by the server now contains 2 extra pieces of information after the date/time:
1. The elapsed time of each API call
2. The total number of RPC calls recorded for the session since it began
As you can see from the sample trace, the elapsed time generated for each line is simply the difference between the times for that line and the preceding 'API>' line. This additional information makes it easier to see which API calls are taking the most time to complete.
If the DMCL code needs to communicate with the Content Server then it will use RPC calls to functions implemented by the server - each call issued is added to a running total and reported in the RPC call number displayed.
At the end of the trace there are 2 extra summary lines for the total tracing time and the total number of RPC calls issued. next
|
|
|
