Getting more from tracebacks

Now that I've spammed my readers with a useless "test post via email" note, I will try to post something of value.

I have always been fond of saying "tracebacks are our friends". In my mind, tracebacks are not to be feared... the bigger the traceback the better because that means that I have more information available to me to debug the problem.

A common debugging technique is to put a call to the !traceback!() procedure in any method from which you want to determine how the call stack arrived at that method. Placing a !traceback!() call in your code won't raise a condition or stop the code flow. It will simply give you a dump of the call stack at that point.

To demonstrate how this works, I have put a !traceback!() call in the Web Map Connector's ve_tile.draw_on() method. The traceback looks as you would expect...

---- traceback: renderer (heavy_thread 3611775) ----
time=14/10/2009 17:00:21
sw!version=4.1.0 (swaf)
os_text_encoding=cp1252
!snapshot_traceback?!=False

!traceback!()
a ve_tile(detached) .draw_on(a sw:canvas)
sw:simple_vector:[1-11].fast_keys_and_elements()
sw:keyed_set(1).valid_indices(False)
sw:keyed_set(1).fast_elements()
sw:keyed_set(1).elements()
transient_rwo_collection(road_tile).fast_elements()
sw:simple_vector:[1-11].fast_keys_and_elements()
sw:hash_table(1).valid_indices(False)
sw:hash_table(1).fast_elements()
ve_dataset(ve_dataset).scan_elements(a bounding_box, sw:rope:[1-1], sw:hash_table(0))
a sw:uds_geometry_set(ve_dataset,0,0).scan_elements(a bounding_box, sw:rope:[1-1], sw:hash_table(0))
a sw:uds_geometry_set(ve_dataset,0,0).elements()
a sw:uds_geometry_set(ve_dataset,0,0).draw_on(a sw:canvas, unset)
sw:rope:[1-4].elements()
a sw:composite_geometry_set.draw_on(a sw:canvas, unset)
a sw:canvas.paint(True, a sw:composite_geometry_set, unset)
a sw:canvas.draw(a sw:composite_geometry_set)
map_view(map(Electricity),region).super(map_view).original!int!do_render(unset)
map_view(map(Electricity),region).int!do_render(unset)
renderer(map_view(map(Electricity),region), unset)
light_thread_launcher_proc_990928()

There is a global variable !snapshot_traceback?! that you set to _true to give you a bit more information.

MagikSF> !snapshot_traceback?! << _true
$

Now the traceback looks like...

---- traceback: renderer (heavy_thread 3563153) ----
time=14/10/2009 17:01:44
sw!version=4.1.0 (swaf)
os_text_encoding=cp1252
!snapshot_traceback?!=True

[1] !traceback!()
[2] a ve_tile(detached) .draw_on(a sw:canvas)
[3] sw:simple_vector:[1-11].fast_keys_and_elements()
[4] sw:keyed_set(1).valid_indices(False)
[5] sw:keyed_set(1).fast_elements()
[6] sw:keyed_set(1).elements()
[7] transient_rwo_collection(road_tile).fast_elements()
[8] sw:simple_vector:[1-11].fast_keys_and_elements()
[9] sw:hash_table(1).valid_indices(False)
[10] sw:hash_table(1).fast_elements()
[11] ve_dataset(ve_dataset).scan_elements(a bounding_box, sw:rope:[1-1], sw:hash_table(0))
[12] a sw:uds_geometry_set(ve_dataset,0,0).scan_elements(a bounding_box, sw:rope:[1-1], sw:hash_table(0))
[13] a sw:uds_geometry_set(ve_dataset,0,0).elements()
[14] a sw:uds_geometry_set(ve_dataset,0,0).draw_on(a sw:canvas, unset)
[15] sw:rope:[1-4].elements()
[16] a sw:composite_geometry_set.draw_on(a sw:canvas, unset)
[17] a sw:canvas.paint(True, a sw:composite_geometry_set, unset)
[18] a sw:canvas.draw(a sw:composite_geometry_set)
[19] map_view(map(Electricity),region).super(map_view).original!int!do_render(unset)
[20] map_view(map(Electricity),region).int!do_render(unset)
[21] renderer(map_view(map(Electricity),region), unset)
[22] light_thread_launcher_proc_990928()

... as you can see, each traceback line is numbered. This is kind of handy to have. The real benefits of !snapshot_traceback?! are described in the public comments for this global variable.

What I wanted to show you is a modification I made to the !traceback!() procedure that gives you even more helpful information whilst !snapshot_traceback?! is _true.

Here is my hack of the !traceback!() procedure.

#% text_encoding = iso8859_1
_package sw
$
_global !traceback! <<
_proc@traceback(_optional stream, max_depth, full?)
       ##  Display traceback of calls in the current thread on
       ##  STREAM. If max_depth is given, at most that number of
       ##  stack frames will be displayed.
       ##
       ##  If !traceback_show_args?! is true, then the arguments will
       ##  be shown along with the method name.
       ##
       ##  Tracebacks normally exclude stack frames after a
       ##  condition.raise(). Setting FULL? to _true will force the
       ##  full traceback to be shown. I.e including tracebacks of any
       ##  condition handlers.

 _thisthread.traceback(stream, !traceback_show_args?!,max_depth, full?)

 _global !snapshot_traceback?!

 _if !snapshot_traceback?! _is _true
 _then
  
  _global !ts!
  _local sfile , meth

  write("These numbered source files correspond to the methods in the numbered lines in the traceback above.")

  _for i,v _over !ts!.fast_keys_and_elements()
  _loop
   meth << v.receiver.method(v.message)
   
   _if meth _is _unset
   _then
    show(write_string("[",i,"]"))
    _continue
   _endif
   
   sfile << meth.source_file
   _dynamic !show_string_length! << sfile.size
   show(write_string("[",i,"]"),sfile)
  _endloop
 _endif
_endproc
$

You can see that it calls the standard _thisthread.traceback() method, but after that it takes a list of all the methods/procedures that were reported in the traceback and shows their source files as well...

---- traceback: renderer (heavy_thread 3514507) ----
time=14/10/2009 17:05:41
sw!version=4.1.0  (swaf)
os_text_encoding=cp1252
!snapshot_traceback?!=True

[1] traceback()
[2] a ve_tile(detached)  .draw_on(a sw:canvas)
[3]               sw:simple_vector:[1-11].fast_keys_and_elements()
[4]             sw:keyed_set(1).valid_indices(False)
[5]           sw:keyed_set(1).fast_elements()
[6]         sw:keyed_set(1).elements()
[7]         transient_rwo_collection(road_tile).fast_elements()
[8]             sw:simple_vector:[1-11].fast_keys_and_elements()
[9]           sw:hash_table(1).valid_indices(False)
[10]         sw:hash_table(1).fast_elements()
[11]       ve_dataset(ve_dataset).scan_elements(a bounding_box, sw:rope:[1-1], sw:hash_table(0))
[12]     a sw:uds_geometry_set(ve_dataset,0,0).scan_elements(a bounding_box, sw:rope:[1-1], sw:hash_table(0))
[13]   a sw:uds_geometry_set(ve_dataset,0,0).elements()
[14] a sw:uds_geometry_set(ve_dataset,0,0).draw_on(a sw:canvas, unset)
[15]   sw:rope:[1-4].elements()
[16] a sw:composite_geometry_set.draw_on(a sw:canvas, unset)
[17] a sw:canvas.paint(True, a sw:composite_geometry_set, unset)
[18] a sw:canvas.draw(a sw:composite_geometry_set)
[19] map_view(map(Electricity),region).super(map_view).original!int!do_render(unset)
[20] map_view(map(Electricity),region).int!do_render(unset)
[21] renderer(map_view(map(Electricity),region), unset)
[22] light_thread_launcher_proc_990928()
These numbered source files correspond to the methods in the numbered lines in the traceback above.
"[1]" "/swdev/streams/leo/release/unshipped/source/sys_core/sys_src/general/procedure.magik"
"[2]" "C:\DOCUME~1\Alfred\LOCALS~1\Temp\TAlfred9412q0"
"[3]" "/swdev/streams/leo/release/unshipped/source/sys_core/sys_src/mixins/ro_indexed_collection_mixin.magik"
"[4]" "/swdev/streams/leo/release/unshipped/source/sys_core/sys_src/new_sys_changes.magik"
"[5]" "/swdev/streams/leo/release/unshipped/source/sys_core/sys_src/convert2_sf/hashing/hash_values_helper.magik"
"[6]" "/swdev/streams/leo/release/unshipped/source/sys_core/sys_src/new_sys_changes.magik"
"[7]" "c:/swdev/build/410/410_PB_WINDOWS/unshipped/source/sys_core/ds_src/dd/dd_collection_mixin.magik"
"[8]" "/swdev/streams/leo/release/unshipped/source/sys_core/sys_src/mixins/ro_indexed_collection_mixin.magik"
"[9]" "/swdev/streams/leo/release/unshipped/source/sys_core/sys_src/new_sys_changes.magik"
"[10]" "/swdev/streams/leo/release/unshipped/source/sys_core/sys_src/convert2_sf/hashing/hash_values_helper.magik"
"[11]" "C:/ifactor/products/workspace/Virtual_Earth_Connector/trunk/modules/ve_som/source\ve_dataset.magik"
"[12]" "C:/Smallworld41/product/modules/sw_core/geometry_vector/source/uds_geometry_set.magik"
"[13]" "C:/Smallworld41/product/modules/sw_core/geometry_vector/source/uds_geometry_set.magik"
"[14]" "C:/Smallworld41/product/modules/sw_core/geometry_vector/source/geometry_set_mixin.magik"
"[15]" "/swdev/streams/leo/release/unshipped/source/sys_core/sys_src/mixins/rope_mixin.magik"
"[16]" "C:/Smallworld41/product/modules/sw_core/geometry_vector/source/composite_geometry_set.magik"
"[17]" "c:/swdev/build/410/410_PB_WINDOWS/unshipped/source/sys_core/mgr_src/user/drawing_surface_mixin.magik"
"[18]" "c:/swdev/build/410/410_PB_WINDOWS/unshipped/source/sys_core/mgr_src/user/drawing_surface_mixin.magik"
"[19]" "C:\ifactor\products\workspace\Virtual_Earth_Connector\trunk\source\patches_z_proposed\p1000001_1_if_vec_map_plugin.magik"
"[20]" "C:\ifactor\products\workspace\Virtual_Earth_Connector\trunk\source\patches_z_proposed\p1000001_1_if_vec_map_plugin.magik"
"[21]" "/swdev/streams/leo/release/unshipped/source/sys_core/sys_src/general/procedure.magik"
"[22]" "/swdev/streams/leo/release/unshipped/source/sys_core/sys_src/general/procedure.magik"

This can be very helpful when you are trying to debug why certain code works in one of your environments but not the other. It can be very helpful to the GE Help Desk team because sending this enhanced traceback will tell them how your call stack is different than the one they are testing in. It will show which methods were changed in patches and in custom code.