Profiling HSL

From HEWIKI
Jump to: navigation, search

Contents

This page contains a list of functions which are used for tracing, profiling, or other types of debugging. They generally have a start and stop function, with the start function starting the collection of tracing or profiling data. Then when the stop function is called, it returns that data, or a subset of it, in a list of string.

All of these functions are built-in, meaning that they are accessible on both client and server.

Profile Chat Command

The /profile command utilizes the external functions to expose it in an easy way.

 /profile [option]
    valid options:
      ON        - Turns on call profiling, use the OFF option to dump to chat.
      OFF       - Turns off call profiling and dumps the results to chat.
      SERVERON  [WORLD] - Turns on call profiling on the area server you're connected to.
                [WORLD] - optional paramenter specifying profiling is done on the world server.
      SERVEROFF [THRESHHOLD] [WORLD] - Turns off call profiling on the area server you're connected to and dumps the results to chat.
                [THRESHHOLD] - optional paramenter specifying the interval threshhold below which data should be ignored.
                [WORLD] - optional paramenter specifying profiling is on the world server.
      AUTOON    - Turns on autoprofiling, this results in a dump to the console.
                  whenever the heroexec performance warning appears.
      AUTOOFF   - Turns off autoprofiling.
      AGGREGATE - Turns on aggregate line profiling for the specified script and function or method
                <SERVER|CLIENT> <ScriptName> <Function Or Method Name>
                <SERVER|CLIENT> OFF [threshhold] [combineLines TRUE|FALSE]
      MEMORY    - Takes aggregated snapshots of all nodes in a GOM over time.
                <SERVER|CLIENT> <ON [FREQUENCY] | OFF | DISPLAY <SCRIPT|NODE> <READABLE|PARSABLE> [COUNT|MEMORY] | CLEAN>
                <SERVER|CLIENT> - the GOM to profile.
                <ON|OFF|DISPLAY|CLEAN> - start, stop, display profiled information, clean up snapshot memory (remember to do this).
                [FREQUENCY] - optional parameter specifying how often to profile (in seconds). Default 1 second.
                <SCRIPT|NODE> - Display memory snapshot by script:function(line) or allocating node.
                <READABLE|PARSABLE|SERIES> - Display in human readable, parsable or series format.
                [COUNT|MEMORY] - Optional parameter used with READABLE to sort by total node count, total bytes.
 

Tracing

Tracing is used to find out exactly which lines in a script or scripts have been running.

StartLineTracing()
StopLineTracing() as list of string

After a StartLineTracing call, each line in a script is recorded in a list. When StopLineTracing is called, it returns that list, so it can be examined. The list will include the line number and script name of every line of code (even subcalls) that ran while the trace was active.

Example of Line Tracing

Note: This is the same section of code in the Line Profiling call below.

public function Make()
  StartLineTracing()
  invWindow as NodeRef of Class GUIControl = createNodeFromPrototype("InventoryWindow")
  invWindow.build = true
  screen as Vector3 = getViewPortSize()
  invWindow.position.x = (screen.x - invWindow.size.x) / 2
  invWindow.position.y = (screen.y - invWindow.size.y) / 2
  refreshWindow()
 
  output as List of String = StopLineTracing()
  foreach line in output
    println(line)
  .
  //
.
 
RESULTS
SCRIPT: 106 InvGUI
SCRIPT: 107 InvGUI
SCRIPT: 108 InvGUI
SCRIPT: 109 InvGUI
SCRIPT: 110 InvGUI
SCRIPT: 111 InvGUI
SCRIPT: 119 InvGUI
SCRIPT: 124 InvGUI
SCRIPT: 125 InvGUI
SCRIPT: 126 InvGUI
SCRIPT: 127 InvGUI
SCRIPT: 128 InvGUI
SCRIPT: 129 InvGUI
SCRIPT: 130 InvGUI
SCRIPT: 131 InvGUI
SCRIPT: 113 InvGUI

Profiling

Profiling is used to find out which processes and lines of script code are taking the most time.

Call Profiling

StartCallProfiling()
StopCallProfiling(threshhold as TimeInterval) as list of string

These functions start and stop a process which keeps track of the events in a particular script or area that are consuming CPU resources. The main difference between them is in quantity of detail. When started with StartCallProfiling, the process looks at everything that is going on, on the client or server where it is called, and compiles a database of those events (MouseOvers, function calls, etc.). When it is stopped with StopCallProfiling, it outputs that database in a sorted list of strings, with the longest duration events (the ones using the most resources) at the top of the list.

It is possible to set a threshhold in the StopCallProfiling call, which says to ignore any events that were smaller than the threshhold (to make the list more manageable).

Theoretically, a Call Profile could be started, and left to run for hours. In practice though, it's usually used to collect about 10 seconds worth of data.

Example of Call Profiling

public function start()
  StartCallProfiling()
.
 
public function stop()
  val as TimeInterval = 0:00:00.0
  output as List of String = StopCallProfiling(val)
  foreach line in output
    println(line)
  .
.

Calling start and then 10-15 seconds later calling stop, while in the GM Lounge and running around, resulted in

RESULTS
 
SCRIPT:  391 millis in script GUIAnimation function GUIANIMATIONTIMER_TICK executed 545 times
SCRIPT:  134 millis in script Input_Movement function ONFRAMEUPDATE executed 1180 times
SCRIPT:   87 millis in script ClientChat function MAIN_WINDOWED_CHAT_ONMOUSEENTER executed 25 times
SCRIPT:   69 millis in script ClientChat function MAIN_WINDOWED_CHAT_ONMOUSELEAVE executed 25 times
SCRIPT:   38 millis in script Input_Camera function ONMOUSEMOVE executed 524 times
SCRIPT:   20 millis in script Input_Mouse function INPUTMOUSEHOVERPOLLTIMER_TICK executed 94 times
SCRIPT:   17 millis in script TargetWindowGUI function DESTROYTARGETWINDOW executed 58 times
SCRIPT:   11 millis in script Input_Movement function ONMOUSEMOVE executed 524 times
SCRIPT:   10 millis in script Input_Command function ONMOUSEMOVE executed 524 times
SCRIPT:    7 millis in script Input_Mouse function ONMOUSEMOVE executed 524 times
SCRIPT:    6 millis in script GUITabs function TAB_ONMOUSECLICK executed 5 times
SCRIPT:    6 millis in script TargetCircleGUI function ADDCIRCLETOTARGET executed 58 times
SCRIPT:    3 millis in script Input_Demo function ONMOUSEMOVE executed 262 times
SCRIPT:    3 millis in script ClientChat function GOTCHATMESSAGE executed 2 times
SCRIPT:    1 millis in script Input_Mouse function ONCMDSTOP executed 1 times
SCRIPT:    1 millis in script Input_Movement function ONCMDSTOP executed 13 times
SCRIPT:    1 millis in script Input_Movement function ONCMDSTART executed 14 times
SCRIPT:    0 millis in script GUITabs function TABS_ONLAYOUT executed 6 times
SCRIPT:    0 millis in script Input_Mouse function ONCMDSTART executed 2 times
SCRIPT:    0 millis in script GUITabs function TAB_ONMOUSEDOWN executed 5 times
SCRIPT:    0 millis in script GUITabs function TAB_ONMOUSEUP executed 5 times
SCRIPT:    0 millis in script Input_Mouse function INPUTDOUBLELEFTCLICKTIMER_TICK executed 1 times
SCRIPT:    0 millis in script Input_Camera function ONCMDSTART executed 2 times
SCRIPT:    0 millis in script Input_Mouse function INPUTMOUSEHOVEROVERTIMER_ONSTART executed 3 times
SCRIPT:    0 millis in script Input_Mouse function INPUTMOUSEHOVEROVERTIMER_ONSTOP executed 3 times
SCRIPT:    0 millis in script Input_Camera function ONCMDSTOP executed 1 times
SCRIPT:    0 millis in script Input_Mouse function INPUTDOUBLELEFTCLICKTIMER_ONSTART executed 1 times
SCRIPT:    0 millis in script Input_Mouse function INPUTDOUBLELEFTCLICKTIMER_ONSTOP executed 1 times

Line Profiling

StartLineProfiling()
StopLineProfiling(threshholdMillis as Float) as list of string

Line Profiling operates similarly to CallProfiling, but at a higher level of detail. It is not left running for long periods of time, and instead should be started and stopped within the same script.

Example of Line Profiling

Note that this example took a total of 335ms, and a Call Profiling ran during the same script segment returned "337 millis in script _CommandHandlerClassMethods". This gives you an example of the difference in the information returned. Note the lines are sorted from longest to shortest which is also different from Line Tracing

function crunchStuff()    // line 261
  var a = 2
  var b = a*a             // line 263
  var c = a/(b+a)
.
 
// lines omitted
 
public function demoIt(player as NodeRef)
  var start = SYSTEM.TIME.RAW
  startLineProfiling()           // line 338
  loop vv from 1 to 49999
    crunchStuff()                // line 340
  .
  var elapsed = SYSTEM.TIME.RAW - start
  foreach line in stopLineProfiling(0)
    $CHAT.CHATPLAYER(player, "", line)
  .
  $CHAT.CHATPLAYER(player, "", "elapsed="+elapsed)
.
 
RESULTS
[Chat]    79741 micros in script ProfDemo line 264 executed 49999 times
[Chat]    62621 micros in script ProfDemo line 340 executed 49999 times
[Chat]    59698 micros in script ProfDemo line 262 executed 49999 times
[Chat]    55883 micros in script ProfDemo line 339 executed 50000 times
[Chat]    46584 micros in script ProfDemo line 263 executed 49999 times
[Chat]    31032 micros in script ProfDemo line 261 executed 49999 times
[Chat]       12 micros in script ProfDemo line 342 executed 1 times
[CHAT]:total: 0.0991751 over 0.328 seconds (90.98%)
[CHAT]:elapsed=335000

Note: There is a descrepancy between the elapsed=0:00:00.328 and the total of 335ms. The reason is the precision of SYSTEM.TIME.RAW which on the test machine appears to be about 10ms.

Aggregate Line Profiling

StartAggregateLineProfiling(script as ScriptRef, functionOrMethodName as String)
StopAggregateLineProfiling(threshholdMillis as Float, combineLines as Boolean) as list of string

Aggregate line profiling is an enhancement to regular line profiling that does 3 additional things:


Memory Profiling

Memory profiling captures snapshots of the server or client GOM and temporarily stores the memory used by all the nodes in said GOM. The specific information recorded about each node is: if it's persistent or not, it's persistent or non-persistent memory footprint, the node that allocated it and the specific script, function and line in HSL where this node was allocated. After profiling is stopped the statistics on the memory usage can be displayed in several different ways.

The following functions are used to profile each node.

// This function should not be used in performance critical code
external function QueryNodes( className as String ) as List of NodeRef
 
// Returns the bytes of memory a node occupies in memory
external function GetMemoryUsageOfNode( of_node as NodeRef ) as Integer
 
// Determine script, function and node that caused the specified node to be instantiated
external function GetNodeCreator( of_node as NodeRef, script_name references String, function_name references String, line_number references ID, me_node_during_creation references ID)

Example of Memory Profiling

The following are some examples of how the profiled information can be displayed by typing in the commands in the chat panel.

/profile memory server display script parsable

 
 Displaying (1) snapshots from the Server GOM
 Snapshot Timestamp:04/26/2011 17:35:35 UTC
 Total Nodes:55
 Total NonPersistent Nodes:52
 Total Persistent Nodes:3
 Total Memory (bytes):73122
 Total NonPersistent Memory:68096
 Total Persistent Memory:5026
 Total Excluded Memory:58358
 Location,Base Class,Total Nodes,Total NonPersistent Nodes,Total Persistent Nodes,Total Memory (bytes),Total NonPersistent Memory,Total Persistent Memory
 HE_AccountClassMethods:HE_PostCharacterActivated(131),,1,1,0,224,224,0
 HE_AccountClassMethods:HE_PostCharacterActivated(131),_ChatHandler,1,1,0,224,224,0
 HE_AreaClassMethods:Debug(54),,1,1,0,224,224,0
 HE_AreaClassMethods:Debug(54),_Configurations,1,1,0,224,224,0
 HE_AreaClassMethods:HE_PostOnAreaLoad(25),,1,1,0,280,280,0
 HE_AreaClassMethods:HE_PostOnAreaLoad(25),_States,1,1,0,280,280,0
 _ACCCClassMethods:_factoryCustomizableCharacterController(21),,1,1,0,626,626,0
 _ACCCClassMethods:_factoryCustomizableCharacterController(21),_Account,1,1,0,626,626,0
 _ACCCClassMethods:_factoryCustomizableCharacterController(47),,1,1,0,1960,1960,0
 _ACCCClassMethods:_factoryCustomizableCharacterController(47),HeroEngine_ACCController,1,1,0,1960,1960,0
 _AreaClassMethods:Debug(677),,1,1,0,392,392,0
 _AreaClassMethods:Debug(677),_Debug,1,1,0,392,392,0
 _AreaClassMethods:_OnAreaLoad(115),,1,1,0,23300,23300,0
 _AreaClassMethods:_OnAreaLoad(115),_EditHandler,1,1,0,23300,23300,0
 _AreaClassMethods:_OnAreaLoad(128),,1,1,0,344,344,0
 _AreaClassMethods:_OnAreaLoad(128),_CharacterCreationSystem,1,1,0,344,344,0
 _AreaClassMethods:_OnAreaLoad(146),,1,1,0,1244,1244,0
 _AreaClassMethods:_OnAreaLoad(146),_World,1,1,0,1244,1244,0
 _AreaClassMethods:_OnAreaLoad(167),,1,1,0,224,224,0
 _AreaClassMethods:_OnAreaLoad(167),_HeroEngineAreaSpinDown,1,1,0,224,224,0
 _AreaClassMethods:_OnAreaLoad(176),,1,1,0,224,224,0
 _AreaClassMethods:_OnAreaLoad(176),_npc,1,1,0,224,224,0
 _AreaClassMethods:_OnPhysicsSceneCreated(30),,1,1,0,492,492,0
 _AreaClassMethods:_OnPhysicsSceneCreated(30),_PathSystem,1,1,0,492,492,0
 _AreaSpinDownSpecClassMethods:CreateFromSpec(8),,1,1,0,456,456,0
 _AreaSpinDownSpecClassMethods:CreateFromSpec(8),_areaSpinDownHandler,1,1,0,456,456,0
 _CommandHandlerClassMethods:_ProcessCommand(26),,1,1,0,224,224,0
 _CommandHandlerClassMethods:_ProcessCommand(26),_permissions,1,1,0,224,224,0
 _HeroEngineProfilingClassMethods:HE_ProcessCommandInput(154),,1,1,0,400,400,0
 _HeroEngineProfilingClassMethods:HE_ProcessCommandInput(154),_HeroEngineProfiling,1,1,0,400,400,0
 _InputHandlerClassMethods:ServerMouseEvent(35),,1,1,0,224,224,0
 _InputHandlerClassMethods:ServerMouseEvent(35),_InputHandler,1,1,0,224,224,0
 _playerAccountClassMethods:_GetReplicationGroup(514),,1,1,0,4456,4456,0
 _playerAccountClassMethods:_GetReplicationGroup(514),_ReplicationGroup,1,1,0,4456,4456,0
 _playerAccountClassMethods:_GetReplicationGroup(536),,1,1,0,2086,2086,0
 _playerAccountClassMethods:_GetReplicationGroup(536),_SpatialAwareness_Area,1,1,0,2086,2086,0
 unknown,,37,34,3,35742,30716,5026
 unknown,AreaAsset,15,15,0,6566,6566,0
 unknown,AreaNode,1,1,0,2294,2294,0
 unknown,AreaRoot,1,1,0,826,826,0
 unknown,GMNoteRoot,1,1,0,280,280,0
 unknown,HeightMapInstance,1,1,0,3758,3758,0
 unknown,PathNode,1,1,0,628,628,0
 unknown,PathPointNode,1,1,0,526,526,0
 unknown,RoomNode,2,2,0,2824,2824,0
 unknown,TriggerInstance,3,3,0,9168,9168,0
 unknown,_ACCC,1,1,0,224,224,0
 unknown,_Area,1,1,0,344,344,0
 unknown,_CommandHandler,1,1,0,224,224,0
 unknown,_PlayerAccount,1,0,1,1530,0,1530
 unknown,_PlayerCharacter,1,0,1,1582,0,1582
 unknown,_PlayerConnection,1,1,0,934,934,0
 unknown,_Repository,1,1,0,1008,1008,0
 unknown,_StateRoot,1,1,0,664,664,0
 unknown,_characterAppearance,1,0,1,1914,0,1914
 unknown,_npcAnchor,1,1,0,224,224,0
 unknown,_seamlessAreaLinkRoot,1,1,0,224,224,0
 

/profile memory server display script series

 Displaying (2) snapshots from the Server GOM
 Location,04/26/2011 17:52:30 UTC Total Bytes,04/26/2011 17:52:31 UTC Total Bytes
 HE_AccountClassMethods:HE_PostCharacterActivated(131),224,224
 HE_AreaClassMethods:Debug(54),224,224
 HE_AreaClassMethods:HE_PostOnAreaLoad(25),280,280
 _ACCCClassMethods:_factoryCustomizableCharacterController(21),626,626
 _ACCCClassMethods:_factoryCustomizableCharacterController(47),1960,1960
 _AreaClassMethods:Debug(677),392,392
 _AreaClassMethods:_OnAreaLoad(115),23300,23300
 _AreaClassMethods:_OnAreaLoad(128),344,344
 _AreaClassMethods:_OnAreaLoad(146),1244,1244
 _AreaClassMethods:_OnAreaLoad(167),224,224
 _AreaClassMethods:_OnAreaLoad(176),224,224
 _AreaClassMethods:_OnPhysicsSceneCreated(30),492,492
 _AreaSpinDownSpecClassMethods:CreateFromSpec(8),456,456
 _CommandHandlerClassMethods:_ProcessCommand(26),224,224
 _HeroEngineProfilingClassMethods:HE_ProcessCommandInput(154),400,432
 _InputHandlerClassMethods:ServerMouseEvent(35),224,224
 _playerAccountClassMethods:_GetReplicationGroup(514),4456,4456
 _playerAccountClassMethods:_GetReplicationGroup(536),2086,2086
 unknown,35742,35742
 

/profile memory server display node series

 Displaying (2) snapshots from the Server GOM
 AllocatingNode,04/26/2011 17:52:30 UTC Total Bytes,04/26/2011 17:52:31 UTC Total Bytes
 0,35742,35742
 113592271518,456,456
 268545511323,6766,6766
 269857651301,26724,26724
 269857651313,2586,2586
 269857651314,224,224
 269857651324,624,656
 

Note: Don't forget to use the command /profile memory server clean after you no longer need the profiling data.

Deprecated Profiling Functions

These two functions have been deprecated and are no longer used:

   StartProfiling()
   DumpProfiling()

See also

Personal tools
Namespaces
Variants
Actions
Navigation
Toolbox