Wednesday, October 14, 2009

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.

5 comments:

IgorGL said...

Hi Alfred. Yes, this is very helpful. It will be useful to modify print_implementors_of(), print_users_of(), print_senders_of() to show the source files along with methods and classes names.
Regards, -Igor

Alfred Sawatzky said...

Hello Igor,

Thanks for the additional suggestions. Those would also be helpful for debugging.

Another candidate for this kind of modification is xprf.basic_report(). Once you have completed an XPRF on some action, you can show all source files.

Alfred

Stefan said...

Hi Alfred,

Do you know the product sw_dev_tools? It contains an application for debugging purposes (..\product\modules\sw_dev_tools) and enhances the traceback, too.

Bye,

Stefan

Alfred Sawatzky said...

Hi Stefan,

Thanks for mentioning sw_dev_tools. I do use it occasionally.

Alfred

Borys Bak said...

Hi Alfred,

In MDT debug perspective you can obtain the same information every time the program execution is suspended. For example on every installed breakpoint when the execution stops, you can see the state of variables and the stacktrace of the current position.

You can see the print screen here.

Regards,
Borys