Using Client Timing Meters
From Multiverse
| Using the Multiverse Client |
|
Install & Run • Supported Graphics Cards • Release Notes • Client FAQ • Troubleshooting • Connecting to a World • Client Metering • Using the Client Log File • Debugging Client Errors |
| Reference |
|
Command Line Syntax • World Settings File • Patcher Page Reference • Client Logging |
Contents |
Overview
The Multiverse Client has a built-in profiler known as the metering facility for for debugging, performance analysis, and optimization. When enabled, it provides a log of metered events including the frequency and duration of function calls. In contrast to a utility such as gprof, metering is intrinsic to the client and you can enable or disable it at run-time.
There are two kinds of timing meters: accumulating and non-accumulating.
For accumulating meters, the meter log collapses times: the first time the Client process enters the meter, the accumulated time for the meter is zeroed. The time inside subsequent enter/exit pairs is added to the accumulated time, but nothing is printed in the report for those inner timings. But when the outer exit call happens, the time displayed is the report is the sum of the elapsed times of the inner calls. This behavior is useful if you want to, for example, add up all the time spent in a particular section of frame rendering, across many frames.
Non-accumulating meters display a pair of rows in the meter report every time the client process enters the meter or exits the meter.
Format of the metering log files
The metering facility creates two log files: the meter log, MeterLog.txt, and the complete meter event log, MeterEvents.txt.
The meter log shows entry and exit events for meters that are encountered by executing code in the client. The first column for entry events is time in microseconds since meterings was enabled; if you typed Ctrl-Alt-Shift-N, it will be the time that the frame being metered started rendering. The number in the first column for exit events is the time in microseconds since the entry event. MeterLog.txt omits meter enter/exit sequences that are smaller than 3 microseconds. Finally, MeterLog.txt contains info events, which contain information like the name of the mesh or material or boundary being rendered.
MeterEvents.txt is laid out just like MeterLog.txt, but contains all enter and exit records, including ones less than three microseconds in duration, and those collapsed into accumulating meters in MeterLog.txt.
Enabling metering
To meter a single frame in the client, type Ctrl-Alt-Shift-N. This will save information on how much time the client spends doing what tasks to the MeterLog.txt and MeterEvents.txt files in client_home directory.
In Python code, turn on metering by calling SystemStatus.ToggleMetering(). To meter a single frame, call SystemStatus.MeterOneFrame(). To begin or end metering the longest frame during a time period, call
SystemStatus.ToggleMeteringLongestFrame().
Example meter log output
Below is an example of a client MeterLog.txt. The lines containing asterisks represent accumulating meter results.
NOTE: Some very long lines have been broken for readability.
Starting meter report for Frame Processing; starting event 0; units are usecs
0 Enter Engine.Engine Frame
1127 |-Enter Engine.Engine OS Events
39 |-Exit Engine.Engine OS Events
1169 |-Enter Engine.Engine Render
1171 |-|-Enter Engine One Frame.Engine One Frame
1174 |-|-|-Enter Engine One Frame.Engine One Frame Started
523 |-|-|-Exit Engine One Frame.Engine One Frame Started
1700 |-|-|-Enter Engine One Frame.Engine One Frame Update
1703 |-|-|-|-Enter Update Target.Update Target
1713 |-|-|-|-|-Enter Update Target.Viewport Update
1716 |-|-|-|-|-|-Enter Render Scene.Render Scene
3032 |-|-|-|-|-|-|-Enter Render Scene.Find Visible
3318 |-|-|-|-|-|-|-|-Enter Entity Queue.Update Animation
3598 |-|-|-|-|-|-|-|-|-Info Updating animation for mesh human_male.mesh,
skeleton human_male.skeleton
3601 |-|-|-|-|-|-|-|-|-Enter Animation Update.Copy Bone
3604 |-|-|-|-|-|-|-|-|-|-Enter Cache Bones.Bone Set Anim State
333 |-|-|-|-|-|-|-|-|-|-Exit Cache Bones.Bone Set Anim State
3939 |-|-|-|-|-|-|-|-|-|-Enter Cache Bones.Bone Get Bones
220 |-|-|-|-|-|-|-|-|-|-Exit Cache Bones.Bone Get Bones
4169 |-|-|-|-|-|-|-|-|-|-Enter Cache Bones.Bone Transform
30 |-|-|-|-|-|-|-|-|-|-Exit Cache Bones.Bone Transform
600 |-|-|-|-|-|-|-|-|-Exit Animation Update.Copy Bone
4207 |-|-|-|-|-|-|-|-|-Enter Animation Update.Software Blend
5 |-|-|-|-|-|-|-|-|-Exit Animation Update.Software Blend
898 |-|-|-|-|-|-|-|-Exit Entity Queue.Update Animation
4224 |-|-|-|-|-|-|-|-Enter Entity Queue.Update Child
11 |-|-|-|-|-|-|-|-Exit Entity Queue.Update Child
4237 |-|-|-|-|-|-|-|-Enter Entity Queue.Update Child
7 |-|-|-|-|-|-|-|-Exit Entity Queue.Update Child
4352 |-|-|-|-|-|-|-|-Enter Entity Queue.Update Animation
4363 |-|-|-|-|-|-|-|-|-Info Updating animation for mesh human_female.mesh,
skeleton human_female.skeleton
4365 |-|-|-|-|-|-|-|-|-Enter Animation Update.Copy Bone
4367 |-|-|-|-|-|-|-|-|-|-Enter Cache Bones.Bone Set Anim State
498 |-|-|-|-|-|-|-|-|-|-Exit Cache Bones.Bone Set Anim State
4868 |-|-|-|-|-|-|-|-|-|-Enter Cache Bones.Bone Get Bones
716 |-|-|-|-|-|-|-|-|-|-Exit Cache Bones.Bone Get Bones
5597 |-|-|-|-|-|-|-|-|-|-Enter Cache Bones.Bone Transform
28 |-|-|-|-|-|-|-|-|-|-Exit Cache Bones.Bone Transform
1261 |-|-|-|-|-|-|-|-|-Exit Animation Update.Copy Bone
5633 |-|-|-|-|-|-|-|-|-Enter Animation Update.Software Blend
4 |-|-|-|-|-|-|-|-|-Exit Animation Update.Software Blend
1292 |-|-|-|-|-|-|-|-Exit Entity Queue.Update Animation
5651 |-|-|-|-|-|-|-|-Enter Entity Queue.Update Child
16 |-|-|-|-|-|-|-|-Exit Entity Queue.Update Child
5669 |-|-|-|-|-|-|-|-Enter Entity Queue.Update Child
12 |-|-|-|-|-|-|-|-Exit Entity Queue.Update Child
5820 |-|-|-|-|-|-|-|-Enter Entity Queue.Update Animation
5826 |-|-|-|-|-|-|-|-|-Info Updating animation for mesh human_male.mesh,
skeleton human_male.skeleton
5828 |-|-|-|-|-|-|-|-|-Enter Animation Update.Copy Bone
5830 |-|-|-|-|-|-|-|-|-|-Enter Cache Bones.Bone Set Anim State
431 |-|-|-|-|-|-|-|-|-|-Exit Cache Bones.Bone Set Anim State
6265 |-|-|-|-|-|-|-|-|-|-Enter Cache Bones.Bone Get Bones
205 |-|-|-|-|-|-|-|-|-|-Exit Cache Bones.Bone Get Bones
6480 |-|-|-|-|-|-|-|-|-|-Enter Cache Bones.Bone Transform
29 |-|-|-|-|-|-|-|-|-|-Exit Cache Bones.Bone Transform
683 |-|-|-|-|-|-|-|-|-Exit Animation Update.Copy Bone
6517 |-|-|-|-|-|-|-|-|-Enter Animation Update.Software Blend
5 |-|-|-|-|-|-|-|-|-Exit Animation Update.Software Blend
706 |-|-|-|-|-|-|-|-Exit Entity Queue.Update Animation
6533 |-|-|-|-|-|-|-|-Enter Entity Queue.Update Child
10 |-|-|-|-|-|-|-|-Exit Entity Queue.Update Child
6545 |-|-|-|-|-|-|-|-Enter Entity Queue.Update Child
7 |-|-|-|-|-|-|-|-Exit Entity Queue.Update Child
6613 |-|-|-|-|-|-|-|-Enter BillboardSet.Notify Camera
6616 |-|-|-|-|-|-|-|-|-Enter BillboardSet.Not Self
5 |-|-|-|-|-|-|-|-|-Exit BillboardSet.Not Self
6623 |-|-|-|-|-|-|-|-|-Enter BillboardSet.Get Buffers
12 |-|-|-|-|-|-|-|-|-Exit BillboardSet.Get Buffers
6637 |-|-|-|-|-|-|-|-|-Enter BillboardSet.Lock Pos Buffer
17645 |-|-|-|-|-|-|-|-|-Exit BillboardSet.Lock Pos Buffer
24285 |-|-|-|-|-|-|-|-|-Enter BillboardSet.Lock Col Buffer
13 |-|-|-|-|-|-|-|-|-Exit BillboardSet.Lock Col Buffer
24300 |-|-|-|-|-|-|-|-|-Enter BillboardSet.Lock Tex
6 |-|-|-|-|-|-|-|-|-Exit BillboardSet.Lock Tex
24309 |-|-|-|-|-|-|-|-|-Enter BillboardSet.Gen Vertices
72 |-|-|-|-|-|-|-|-|-Exit BillboardSet.Gen Vertices
17788 |-|-|-|-|-|-|-|-Exit BillboardSet.Notify Camera
22365 |-|-|-|-|-|-|-Exit Render Scene.Find Visible
25455 |-|-|-|-|-|-|-Enter Render Scene.Render Objects
25460 |-|-|-|-|-|-|-|-Enter Client.Render Queue Timer
3 |-|-|-|-|-|-|-|-Exit Client.Render Queue Timer
25465 |-|-|-|-|-|-|-|-Enter Client.Render Queue Timer
25468 |-|-|-|-|-|-|-|-|-Enter Render Visible.Render Group Objects
25470 |-|-|-|-|-|-|-|-|-|-Enter Render Queue Group.Render Queue Group
25474 |-|-|-|-|-|-|-|-|-|-|-Enter MVSM Render Solid.Base Render
25476 |-|-|-|-|-|-|-|-|-|-|-|-Enter *Render Single.Do Light
25478 |-|-|-|-|-|-|-|-|-|-|-|-Enter *Render Single.Update Auto Parms
25480 |-|-|-|-|-|-|-|-|-|-|-|-Enter *Render Single.Set Gpu Parms
25482 |-|-|-|-|-|-|-|-|-|-|-|-Enter *Render Single.Use Lights
25484 |-|-|-|-|-|-|-|-|-|-|-|-Enter *Render Single.Render Op
25626 |-|-|-|-|-|-|-|-|-|-|-|-Info Rendering material 'SkyBoxPlane2'
25704 |-|-|-|-|-|-|-|-|-|-|-|-Info Rendering material 'SkyBoxPlane1'
25755 |-|-|-|-|-|-|-|-|-|-|-|-Info Rendering material 'SkyBoxPlane4'
25804 |-|-|-|-|-|-|-|-|-|-|-|-Info Rendering material 'SkyBoxPlane5'
25861 |-|-|-|-|-|-|-|-|-|-|-|-Info Rendering material 'SkyBoxPlane3'
25911 |-|-|-|-|-|-|-|-|-|-|-|-Info Rendering material 'SkyBoxPlane0'
64 |-|-|-|-|-|-|-|-|-|-|-|-Exit *Render Single.Render Op
0 |-|-|-|-|-|-|-|-|-|-|-|-Exit *Render Single.Use Lights
0 |-|-|-|-|-|-|-|-|-|-|-|-Exit *Render Single.Set Gpu Parms
0 |-|-|-|-|-|-|-|-|-|-|-|-Exit *Render Single.Update Auto Parms
180 |-|-|-|-|-|-|-|-|-|-|-|-Exit *Render Single.Do Light
463 |-|-|-|-|-|-|-|-|-|-|-Exit MVSM Render Solid.Base Render
25939 |-|-|-|-|-|-|-|-|-|-|-Enter MVSM Render Solid.Boundary Render
26170 |-|-|-|-|-|-|-|-|-|-|-|-Info Rendering boundary 'boundary1 - unique boundary - 0',
semantic of type 'SpeedTreeForest'
27698 |-|-|-|-|-|-|-|-|-|-|-|-Info Rendering boundary 'boundary2 - unique boundary - 1',
semantic of type 'SpeedTreeForest'
34670 |-|-|-|-|-|-|-|-|-|-|-|-Info Rendering boundary 'boundary8 - unique boundary - 2',
semantic of type 'VegetationSemantic'
8734 |-|-|-|-|-|-|-|-|-|-|-Exit MVSM Render Solid.Boundary Render
9208 |-|-|-|-|-|-|-|-|-|-Exit Render Queue Group.Render Queue Group
9213 |-|-|-|-|-|-|-|-|-Exit Render Visible.Render Group Objects
9218 |-|-|-|-|-|-|-|-Exit Client.Render Queue Timer
34690 |-|-|-|-|-|-|-|-Enter Client.Render Queue Timer
34692 |-|-|-|-|-|-|-|-|-Enter Render Visible.Render Group Objects
34694 |-|-|-|-|-|-|-|-|-|-Enter Render Queue Group.Render Queue Group
34699 |-|-|-|-|-|-|-|-|-|-|-Enter MVSM Render Solid.Base Render
34701 |-|-|-|-|-|-|-|-|-|-|-|-Enter *Render Single.Do Light
34703 |-|-|-|-|-|-|-|-|-|-|-|-Enter *Render Single.Update Auto Parms
34705 |-|-|-|-|-|-|-|-|-|-|-|-Enter *Render Single.Set Gpu Parms
34707 |-|-|-|-|-|-|-|-|-|-|-|-Enter *Render Single.Use Lights
34709 |-|-|-|-|-|-|-|-|-|-|-|-Enter *Render Single.Render Op
12315 |-|-|-|-|-|-|-|-|-|-|-Exit MVSM Render Solid.Base Render
47016 |-|-|-|-|-|-|-|-|-|-|-Enter MVSM Render Solid.Boundary Render
47025 |-|-|-|-|-|-|-|-|-|-|-|-Info Rendering boundary 'boundary1 - unique boundary - 0',
semantic of type 'SpeedTreeForest'
47876 |-|-|-|-|-|-|-|-|-|-|-|-Info Rendering boundary 'boundary2 - unique boundary - 1',
semantic of type 'SpeedTreeForest'
54850 |-|-|-|-|-|-|-|-|-|-|-|-Info Rendering boundary 'boundary8 - unique boundary - 2',
semantic of type 'VegetationSemantic'
7838 |-|-|-|-|-|-|-|-|-|-|-Exit MVSM Render Solid.Boundary Render
55624 |-|-|-|-|-|-|-|-|-|-|-Enter *Render Single.Do Light
55631 |-|-|-|-|-|-|-|-|-|-|-Info Rendering material 'smoke'
55645 |-|-|-|-|-|-|-|-|-|-|-Enter *Render Single.Render Op
0 |-|-|-|-|-|-|-|-|-|-|-Exit *Render Single.Render Op
0 |-|-|-|-|-|-|-|-|-|-|-Exit *Render Single.Do Light
20970 |-|-|-|-|-|-|-|-|-|-Exit Render Queue Group.Render Queue Group
20974 |-|-|-|-|-|-|-|-|-Exit Render Visible.Render Group Objects
20980 |-|-|-|-|-|-|-|-Exit Client.Render Queue Timer
55679 |-|-|-|-|-|-|-|-Enter Client.Render Queue Timer
55682 |-|-|-|-|-|-|-|-|-Enter Client.Prepare Overlay Timer
3901 |-|-|-|-|-|-|-|-|-Exit Client.Prepare Overlay Timer
59586 |-|-|-|-|-|-|-|-|-Enter Client.Render Overlay Timer
995 |-|-|-|-|-|-|-|-|-Exit Client.Render Overlay Timer
4905 |-|-|-|-|-|-|-|-Exit Client.Render Queue Timer
35133 |-|-|-|-|-|-|-Exit Render Scene.Render Objects
58875 |-|-|-|-|-|-Exit Render Scene.Render Scene
58880 |-|-|-|-|-Exit Update Target.Viewport Update
58903 |-|-|-|-Exit Update Target.Update Target
59003 |-|-|-Exit Engine One Frame.Engine One Frame Update
60705 |-|-|-Enter Engine One Frame.Engine One Frame Ended
60715 |-|-|-|-Enter Client.Client Frame
60721 |-|-|-|-|-Enter Client.Client Message Handling
4 |-|-|-|-|-Exit Client.Client Message Handling
60728 |-|-|-|-|-Enter Client.Client WorldMgr
60731 |-|-|-|-|-|-Enter WorldManager.Tick Nodes
71 |-|-|-|-|-|-Exit WorldManager.Tick Nodes
79 |-|-|-|-|-Exit Client.Client WorldMgr
60810 |-|-|-|-|-Enter Client.Client Input Handling
60812 |-|-|-|-|-|-Enter Input.Capture Input
182 |-|-|-|-|-|-Exit Input.Capture Input
60997 |-|-|-|-|-|-Enter Input.Immediate Keys
5 |-|-|-|-|-|-Exit Input.Immediate Keys
61004 |-|-|-|-|-|-Enter Input.Apply Immediate
67 |-|-|-|-|-|-Exit Input.Apply Immediate
264 |-|-|-|-|-Exit Client.Client Input Handling
360 |-|-|-|-Exit Client.Client Frame
373 |-|-|-Exit Engine One Frame.Engine One Frame Ended
59910 |-|-Exit Engine One Frame.Engine One Frame
59914 |-Exit Engine.Engine Render
61085 Exit Engine.Engine Frame
