HXCPP Built-in Debugging

The latest version of hxcpp has increased control over how much debugging information is included in the compiled code, as well as some built-in debugging and profiling tools.

Debugging is normally added with the -debug flag to the compiler. This flag turns off compiler optimisation, adds source-line and call-stack tracking and adds additional runtime checks – eg for null pointer access. This is useful for locating problems, but it can make the code run several times slower.

Depending on the application, you may not need all these debugging features. For example, if you do not intend to attach a native debugger, then you probably do not need to turn off compiler optimisations. If you are trying to profile the code, you probably only want the call-stack symbols, but not the other runtime checks. These scenarios are now supported by HXCPP, via compiler defines.

Quick recap: To add a define to the haxe compiler, you can use the “-D DEFINE” syntax on the command line or hxml file, or <haxedef name="DEFINE" /> from an nmml file.

Now, for testing performance, I will be using BunnyMark, and add bunnies until there the a measurable drop in performance. In this case, I added 20000 bunnies to get a frame-rate of about 50fps on my macbook air.

Adding the -debug flag brings the frame-rate down to about 40fps. This is not a huge drop – I guess because the CPU is not that taxed, it the the GPU that is doing more work.

So instead of adding the -debug flag, we can add various defines to achieve the effect we are after.

HXCPP_DEBUG_LINK

Adding this define will keep the symbol tables in the final executable. This is probably not something you want to do in your final release build for external use, but it is something that that is good to have otherwise. This flag will allow you to get meaningful information if you attach your system debugger. Runtime performance hit: none.

DHXCPP_STACK_TRACE

This define will allow you to get a haxe stack trace that includes function names when an exception is thrown, or when the stack is queried directly. There is a small overhead incurred per function call when this is on. Runtime performance hit: very small.

HXCPP_STACK_LINE

This define implies DHXCPP_STACK_TRACE and adds line numbers to the function names. There is additional overhead per line of haxe code, however I had trouble measuring this overhead on the bunnymark – probably because it is not too CPU intensive. Runtime performance hit: small to medium.

HXCPP_CHECK_POINTER

This define explicitly checks pointers for null access and throws an informative exception, rather than just crashing. There is an overhead per member-access. Again, for the bunnymark, it was hard to measure a slowdown. Runtime performance hit: small.

So, these defines can be added without using the -debug flag, which removes the compiler optimisations, which accounts for over 80% of the performance drop.

Built-in Profiler

So where is all the time spent? To answer this question, you can use the built-in profiler. The profiler needs HXCPP_STACK_TRACE, and is started by calling cpp.vm.Profiler.start(filename) from the haxe thread you are interested in. You can call this, say, in response to a button-press, but in this example, I will call it from the mainline. You can provide a log filename, or you can just let it write to stdout. If you use a relative filename in an nme project, the file will be written into the executable directory.

  private static function create()
  {
     cpp.vm.Profiler.start("log.txt");
     Lib.current.addChild (new BunnyMark());
  }

We can then analyse the log. The entries are sorted by total time (including child calls) spent in the routine. The first few are all about 100%, as they look for somewhere to delegate the actual work to. Soon enough, we get to this entry:

Stage::nmeRender 95.60%/0.07%
   DisplayObjectContainer::nmeBroadcast 39.6%
   extern::cffi 60.3%
   (internal) 0.1%

Here the Stage::nmeRender call is almost always active, and is broadcasting an event (the ENTER_FRAME event) for 40% of its time, and calling into cffi (nme c++ render code) for 60% of the time. So we have learnt something already.

You can trace ENTER_FRAME the calls though the event dispatcher until we get to the routine actually in bunnymark:

TileTest::enterFrame 36.55%/8.26%
   Lib::getTimer 0.1%
   Tilesheet::drawTiles 70.2%
   Graphics::clear 6.6%
   DisplayObject::nmeSetY 0.0%
   DisplayObject::nmeSetX 0.0%
   DisplayObject::nmeGetWidth 0.2%
   DisplayObject::nmeGetHeight 0.1%
   DisplayObject::nmeGetGraphics 0.2%
   GC::realloc 0.1%
   (internal) 22.6%

Here the “36.55%/8.26%” means that 35% of the total exe time is spent in this routine, including its children, but only 8% of the total time is spent internally (ie, not in child calls).

And, looking at the drawTiles call:

Tilesheet::drawTiles 25.65%/0.01%
   Graphics::drawTiles 99.9%
   (internal) 0.1%

We see 25% of the total time is spend in the NME Graphics::drawTiles call. So this app spends 60% of the time in drawing routine, and 25% of the time in preparing the draw call. From this, you can assume that it is pretty well optimised!

It is also interesting to note the GC entry:

GC::new 0.17%/0.15%
   GC::collect 12.0%
   (internal) 88.0%

Which is very small, indicating that techniques such as object pooling would have no effect here.

This technique is available on all platforms – you just might have to be a little bit careful about where you write your output file.

Built-in Debugger

The built-in debugger requires you to compile with the HXCPP_DEBUGGER define. Starting the debugger is similar to starting the profiler.

  private static function create()
  {
     new hxcpp.DebugStdio(true);
     Lib.current.addChild (new BunnyMark());
  }

You will note that the “DebugStdio” class is in the hxcpp project, so you will need to add the “-lib hxcpp” command, or via nmml: < haxelib name="hxcpp" />.

The “true” parameter means that the debugger stops as soon as you hit this line. This allows you to set breakpoints etc. Running the above, I get an empty display window (no draw calls have been made yet), and a prompt on the command line:

debug>stopped.
debug>h
help  - print this message
break [file line] - pause execution of one thread [when at certain point]
breakpoints - list breakpoints
delete N - delete breakpoint N
cont  - continue execution
where - print call stack
files - print file list that may be used with breakpoints
vars - print local vars for frame
array limit N - show at most N array elements
mem - print memory usage
collect - run Gc collection
compact - reduce memory usage
exit  - exit programme
bye  - stop debugging, keep running
ok
debug>

Entering “files” shows the input files with indexes 0 to 93. You can use either the filename or file number for setting breakpoints. For example:

debug>break BunnyMark.hx 41

Will set a breakpoint for line 41 on BunnyMark.hx. Currently, you are going to need to have the file handy to look up the line number. So now we want to go back to executing:

debug> c

And immediately, the debugger prints “stopped”. This is because the breakpoint has been hit. To find out where, you can use the “w” command:

debug>stopped.
w
Must break first.
debug>where
*1:FilePos(Method(BunnyMark,addedToStage),BunnyMark.hx,41)
 2:FilePos(Method(Listener,dispatchEvent),neash/events/EventDispatcher.hx,181)
 3:FilePos(Method(EventDispatcher,dispatchEvent),neash/events/EventDispatcher.hx,80)
 4:FilePos(Method(DisplayObject,nmeDispatchEvent),neash/display/DisplayObject.hx,315)
 5:FilePos(Method(DisplayObject,dispatchEvent),neash/display/DisplayObject.hx,198)
 6:FilePos(Method(DisplayObject,nmeOnAdded),neash/display/DisplayObject.hx,458)
 7:FilePos(Method(DisplayObjectContainer,nmeOnAdded),neash/display/DisplayObjectContainer.hx,183)
 8:FilePos(Method(DisplayObject,nmeSetParent),neash/display/DisplayObject.hx,659)
 9:FilePos(Method(DisplayObjectContainer,addChild),neash/display/DisplayObjectContainer.hx,31)
 10:FilePos(Method(BunnyMark,create),BunnyMark.hx,81)
 11:FilePos(Method(BunnyMark,main),BunnyMark.hx,69)
 12:FilePos(Method(Reflect,callMethod),Reflect.hx,55)
 13:FilePos(Method(*,_Function_1_1),ApplicationMain.hx,59)
 14:FilePos(Method(*,_Function_1_1),neash/Lib.hx,75)
 15:FilePos(Method(extern,cffi),/Users/hugh/dev/code.google/hxcpp/src/hx/Lib.cpp,130)
 16:FilePos(Method(Lib,create),neash/Lib.hx,64)
 17:FilePos(Method(Lib,create),nme/Lib.hx,60)
 18:FilePos(Method(ApplicationMain,main),ApplicationMain.hx,39)
ok

The “you must break first” is a little bug in the debugger due to the fact that the break is async. But trying again seems to have fixed this. So here you can see the full call stack. Using the “vars” command shows the local variables, and using the “p” command (short for “print”) shows the values.

debug>vars
[e,this]
ok
debug>p e
nmeIsCancelledNow=false
nmeIsCancelled=false
_type=addedToStage
_target=BunnyMark
_eventPhase=1
_currentTarget=BunnyMark
_cancelable=false
_bubbles=false
type=addedToStage
target=BunnyMark
eventPhase=1
currentTarget=BunnyMark
cancelable=false
bubbles=false
ok
debug>p this
fps=FPS
bg=Background
useHandCursor=false
buttonMode=false
nmeChildren=2 elements
tabChildren=false
numChildren=2
mouseChildren=true
nmeMouseEnabled=true
needsSoftKeyboard=false
moveForSoftKeyboard=false
mouseEnabled=true
doubleClickEnabled=false
nmeScrollRect=(null)
nmeScale9Grid=(null)
nmeParent=neash.display.MovieClip
nmeID=3
nmeGraphicsCache=(null)
nmeFilters=(null)
y=0
x=0
width=580
visible=true
transform=neash.geom.Transform
stage=neash.display.Stage
scrollRect=(null)
scaleY=1
scaleX=1
scale9Grid=(null)
rotation=0
parent=neash.display.MovieClip
opaqueBackground=(null)
nmeHandle=null
name=BunnyMark 3
mouseY=0
mouseX=0
mask=(null)
height=740
graphics=neash.display.Graphics
filters=(empty)
pixelSnapping=NEVER
pedanticBitmapCaching=false
cacheAsBitmap=false
blendMode=NORMAL
alpha=1
nmeTarget=BunnyMark
nmeEventMap=Hash
ok

So now we have a little fun (in a very nerdy sort of way):

debug>set fps.y = 200
ok
debug>cont
running

And you can see that the fps counter has moved down the screen. The more astute reader will notice that the “y” member is actually a “property” and that setting this property has actually caused some haxe code to be run. You can also print the value of a function call to get arbitrary functions to run.
While the code is running you can use “break” to stop it wherever it happens to be.
Using the “exit” command is a quick way out – this can be useful on android when you want to make sure the process is actually dead.

You can jump into a different function on the stack via the "frame" command (notice the "*" has moved), and examine the vars there:

 => frame 17
ok
 => where
 1:FilePos(Method(BunnyMark,addedToStage),BunnyMark.hx,41)
 2:FilePos(Method(Listener,dispatchEvent),neash/events/EventDispatcher.hx,181)
 3:FilePos(Method(EventDispatcher,dispatchEvent),neash/events/EventDispatcher.hx,80)
 4:FilePos(Method(DisplayObject,nmeDispatchEvent),neash/display/DisplayObject.hx,315)
 5:FilePos(Method(DisplayObject,dispatchEvent),neash/display/DisplayObject.hx,198)
 6:FilePos(Method(DisplayObject,nmeOnAdded),neash/display/DisplayObject.hx,458)
 7:FilePos(Method(DisplayObjectContainer,nmeOnAdded),neash/display/DisplayObjectContainer.hx,183)
 8:FilePos(Method(DisplayObject,nmeSetParent),neash/display/DisplayObject.hx,659)
 9:FilePos(Method(DisplayObjectContainer,addChild),neash/display/DisplayObjectContainer.hx,31)
 10:FilePos(Method(BunnyMark,create),BunnyMark.hx,81)
 11:FilePos(Method(BunnyMark,main),BunnyMark.hx,70)
 12:FilePos(Method(Reflect,callMethod),Reflect.hx,55)
 13:FilePos(Method(*,_Function_1_1),ApplicationMain.hx,59)
 14:FilePos(Method(*,_Function_1_1),neash/Lib.hx,75)
 15:FilePos(Method(extern,cffi),/Users/hugh/dev/code.google/hxcpp/src/hx/Lib.cpp,130)
 16:FilePos(Method(Lib,create),neash/Lib.hx,64)
*17:FilePos(Method(Lib,create),nme/Lib.hx,60)
 18:FilePos(Method(ApplicationMain,main),ApplicationMain.hx,39)
ok
 => vars
[icon,title,flags,color,frameRate,height,width,onLoaded]
ok
 => p title
BunnyMark

The command line is all well and good for desktop apps, but it is not much use for mobile apps. To use the debugger on mobile, you can create a debug socket server - the mobile will then connect over WiFi. On your desktop, create and run the hxcpp DdebugTool:

haxe -main hxcpp.DebugTool -lib hxcpp -neko server.n
neko server.n
Waiting for connection on 192.168.0.12:8080

You can see the ip:port that the server is waiting on. Then, back in your code, replace the "DebugStdio" line with a "DebugSocket" line, using the ip:port from the server:

private static function create()
{
   new hxcpp.DebugSocket("192.168.0.12",8080,true);
   Lib.current.addChild (new BunnyMark());
}

And then the operation is exactly the same as before.

The debug code is designed to allow different protocols and backends. It should be possible to replace the code in the hxcpp library with code of your own to present the debug information in any way you like. The "worker" classes are in cpp.vm.Debugger, and you can build your own debugger on top of these.
As a final trick, you can call the debugger functions directly (eg, to always add a breakpoint), or cpp.vm.Debugger.breakBad() (I've been watching too much TV) to allow complex conditions to generate breakpoints, eg:

   if (items.length>0 && !found)
      Debugger.breakBad(); // WTF ?