[trace] Fix tests: tracing-ms, and tracing-categories.

[simgrid.git] / examples / msg / tracing / ms.tesh

diff --git a/examples/msg/tracing/ms.tesh b/examples/msg/tracing/ms.tesh
index b588fe0..fb75e86 100644 (file)
--- a/examples/msg/tracing/ms.tesh
+++ b/examples/msg/tracing/ms.tesh
@@ -2,8 +2,10 @@
 
 p Tracing master/slave application
 
-$ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/filename:tracing/ms.trace --cfg=tracing/categorized:1 --cfg=tracing/uncategorized:1 --cfg=triva/categorized:tracing/ms.cat.plist --cfg=triva/uncategorized:tracing/ms.uncat.plist --log=instr_paje.thres:debug --log=instr_paje_trace.thres:debug "--log=root.fmt:[%10.6r]%e\(%i:%P@%h\)%e%m%n" ${srcdir:=.}/tracing/platform.xml ${srcdir:=.}/tracing/deployment.xml
+$ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/buffer:1 --cfg=tracing/buffer:1 --cfg=tracing/filename:tracing/ms.trace --cfg=tracing/categorized:1 --cfg=tracing/uncategorized:1 --cfg=triva/categorized:tracing/ms.cat.plist --cfg=triva/uncategorized:tracing/ms.uncat.plist --log=instr_paje.thres:debug --log=instr_paje_trace.thres:debug "--log=root.fmt:[%10.6r]%e\(%i:%P@%h\)%e%m%n" ${srcdir:=.}/tracing/platform.xml ${srcdir:=.}/tracing/deployment.xml
 > [  0.000000] (0:@) Configuration change: Set 'tracing' to '1'
+> [  0.000000] (0:@) Configuration change: Set 'tracing/buffer' to '1'
+> [  0.000000] (0:@) Configuration change: Set 'tracing/buffer' to '1'
 > [  0.000000] (0:@) Configuration change: Set 'tracing/filename' to 'tracing/ms.trace'
 > [  0.000000] (0:@) Configuration change: Set 'tracing/categorized' to '1'
 > [  0.000000] (0:@) Configuration change: Set 'tracing/uncategorized' to '1'
@@ -540,13 +542,13 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  0.017364] (0:@) TRACE_paje_dump_buffer: ends
 > [  0.168126] (0:@) new_pajeSetVariable: event_type=8, timestamp=0.017364
 > [  0.168126] (0:@) insert_into_buffer: insert event_type=8, timestamp=0.017364, buffersize=2)
-> [  0.168126] (0:@) insert_into_buffer: inserted at end
+> [  0.168126] (0:@) insert_into_buffer: inserted at end, pos = 2
 > [  0.168126] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.017364
 > [  0.168126] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.017364, buffersize=3)
 > [  0.168126] (0:@) insert_into_buffer: inserted at end, pos = 3
 > [  0.168126] (0:@) new_pajeSubVariable: event_type=10, timestamp=0.168126
 > [  0.168126] (0:@) insert_into_buffer: insert event_type=10, timestamp=0.168126, buffersize=4)
-> [  0.168126] (0:@) insert_into_buffer: inserted at end
+> [  0.168126] (0:@) insert_into_buffer: inserted at end, pos = 4
 > [  0.168126] (0:@) new_pajeSetVariable: event_type=8, timestamp=0.017364
 > [  0.168126] (0:@) insert_into_buffer: insert event_type=8, timestamp=0.017364, buffersize=5)
 > [  0.168126] (0:@) insert_into_buffer: inserted at 4
@@ -586,13 +588,13 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  0.188676] (0:@) TRACE_paje_dump_buffer: ends
 > [  0.386279] (0:@) new_pajeSetVariable: event_type=8, timestamp=0.188676
 > [  0.386279] (0:@) insert_into_buffer: insert event_type=8, timestamp=0.188676, buffersize=16)
-> [  0.386279] (0:@) insert_into_buffer: inserted at end
+> [  0.386279] (0:@) insert_into_buffer: inserted at end, pos = 16
 > [  0.386279] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.188676
 > [  0.386279] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.188676, buffersize=17)
 > [  0.386279] (0:@) insert_into_buffer: inserted at end, pos = 17
 > [  0.386279] (0:@) new_pajeSubVariable: event_type=10, timestamp=0.386279
 > [  0.386279] (0:@) insert_into_buffer: insert event_type=10, timestamp=0.386279, buffersize=18)
-> [  0.386279] (0:@) insert_into_buffer: inserted at end
+> [  0.386279] (0:@) insert_into_buffer: inserted at end, pos = 18
 > [  0.386279] (0:@) new_pajeSetVariable: event_type=8, timestamp=0.188676
 > [  0.386279] (0:@) insert_into_buffer: insert event_type=8, timestamp=0.188676, buffersize=19)
 > [  0.386279] (0:@) insert_into_buffer: inserted at 18
@@ -719,7 +721,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  0.511874] (0:@) insert_into_buffer: inserted at end, pos = 58
 > [  0.511874] (0:@) new_pajeSubVariable: event_type=10, timestamp=0.511874
 > [  0.511874] (0:@) insert_into_buffer: insert event_type=10, timestamp=0.511874, buffersize=59)
-> [  0.511874] (0:@) insert_into_buffer: inserted at end
+> [  0.511874] (0:@) insert_into_buffer: inserted at end, pos = 59
 > [  0.511874] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.386279
 > [  0.511874] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.386279, buffersize=60)
 > [  0.511874] (0:@) insert_into_buffer: inserted at 59
@@ -775,7 +777,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  0.526739] (0:@) insert_into_buffer: inserted at end, pos = 76
 > [  0.526739] (0:@) new_pajeSubVariable: event_type=10, timestamp=0.526739
 > [  0.526739] (0:@) insert_into_buffer: insert event_type=10, timestamp=0.526739, buffersize=77)
-> [  0.526739] (0:@) insert_into_buffer: inserted at end
+> [  0.526739] (0:@) insert_into_buffer: inserted at end, pos = 77
 > [  0.526739] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.511874
 > [  0.526739] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.511874, buffersize=78)
 > [  0.526739] (0:@) insert_into_buffer: inserted at 77
@@ -818,10 +820,10 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  0.547074] (0:@) TRACE_paje_dump_buffer: ends
 > [  0.742611] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.547074
 > [  0.742611] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.547074, buffersize=90)
-> [  0.742611] (0:@) insert_into_buffer: inserted at end
+> [  0.742611] (0:@) insert_into_buffer: inserted at end, pos = 90
 > [  0.742611] (0:@) new_pajeSubVariable: event_type=10, timestamp=0.742611
 > [  0.742611] (0:@) insert_into_buffer: insert event_type=10, timestamp=0.742611, buffersize=91)
-> [  0.742611] (0:@) insert_into_buffer: inserted at end
+> [  0.742611] (0:@) insert_into_buffer: inserted at end, pos = 91
 > [  0.742611] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.547074
 > [  0.742611] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.547074, buffersize=92)
 > [  0.742611] (0:@) insert_into_buffer: inserted at 91
@@ -962,19 +964,19 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  0.744775] (0:@) TRACE_paje_dump_buffer: ends
 > [  0.744775] (2:slave@Tremblay) new_pajeAddVariable: event_type=9, timestamp=0.744775
 > [  0.744775] (2:slave@Tremblay) insert_into_buffer: insert event_type=9, timestamp=0.744775, buffersize=106)
-> [  0.744775] (2:slave@Tremblay) insert_into_buffer: inserted at end
+> [  0.744775] (2:slave@Tremblay) insert_into_buffer: inserted at end, pos = 106
 > [  0.744775] (1:master@Tremblay) new_pajeSetVariable: event_type=8, timestamp=0.744775
 > [  0.744775] (1:master@Tremblay) insert_into_buffer: insert event_type=8, timestamp=0.744775, buffersize=107)
 > [  0.744775] (1:master@Tremblay) insert_into_buffer: inserted at end, pos = 107
 > [  0.823468] (0:@) new_pajeSetVariable: event_type=8, timestamp=0.168126
 > [  0.823468] (0:@) insert_into_buffer: insert event_type=8, timestamp=0.168126, buffersize=108)
-> [  0.823468] (0:@) insert_into_buffer: inserted at 0
+> [  0.823468] (0:@) insert_into_buffer: inserted at beginning
 > [  0.823468] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.168126
 > [  0.823468] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.168126, buffersize=109)
 > [  0.823468] (0:@) insert_into_buffer: inserted at 1
 > [  0.823468] (0:@) new_pajeSubVariable: event_type=10, timestamp=0.823468
 > [  0.823468] (0:@) insert_into_buffer: insert event_type=10, timestamp=0.823468, buffersize=110)
-> [  0.823468] (0:@) insert_into_buffer: inserted at end
+> [  0.823468] (0:@) insert_into_buffer: inserted at end, pos = 110
 > [  0.823468] (0:@) new_pajeSetVariable: event_type=8, timestamp=0.168126
 > [  0.823468] (0:@) insert_into_buffer: insert event_type=8, timestamp=0.168126, buffersize=111)
 > [  0.823468] (0:@) insert_into_buffer: inserted at 2
@@ -1082,10 +1084,10 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  0.838668] (0:@) TRACE_paje_dump_buffer: ends
 > [  0.989430] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.838668
 > [  0.989430] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.838668, buffersize=68)
-> [  0.989430] (0:@) insert_into_buffer: inserted at end
+> [  0.989430] (0:@) insert_into_buffer: inserted at end, pos = 68
 > [  0.989430] (0:@) new_pajeSubVariable: event_type=10, timestamp=0.989430
 > [  0.989430] (0:@) insert_into_buffer: insert event_type=10, timestamp=0.989430, buffersize=69)
-> [  0.989430] (0:@) insert_into_buffer: inserted at end
+> [  0.989430] (0:@) insert_into_buffer: inserted at end, pos = 69
 > [  0.989430] (0:@) TRACE_paje_dump_buffer: dump until 0.386279. starts
 > [  0.989430] (0:@) TRACE_paje_dump_buffer: ends
 > [  0.989430] (1:master@Tremblay) new_pajeSetVariable: event_type=8, timestamp=0.989430
@@ -1108,13 +1110,13 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  0.989430] (0:@) insert_into_buffer: inserted at end, pos = 75
 > [  1.041621] (0:@) new_pajeSetVariable: event_type=8, timestamp=0.386279
 > [  1.041621] (0:@) insert_into_buffer: insert event_type=8, timestamp=0.386279, buffersize=76)
-> [  1.041621] (0:@) insert_into_buffer: inserted at 0
+> [  1.041621] (0:@) insert_into_buffer: inserted at beginning
 > [  1.041621] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.386279
 > [  1.041621] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.386279, buffersize=77)
 > [  1.041621] (0:@) insert_into_buffer: inserted at 1
 > [  1.041621] (0:@) new_pajeSubVariable: event_type=10, timestamp=1.041621
 > [  1.041621] (0:@) insert_into_buffer: insert event_type=10, timestamp=1.041621, buffersize=78)
-> [  1.041621] (0:@) insert_into_buffer: inserted at end
+> [  1.041621] (0:@) insert_into_buffer: inserted at end, pos = 78
 > [  1.041621] (0:@) new_pajeSetVariable: event_type=8, timestamp=0.386279
 > [  1.041621] (0:@) insert_into_buffer: insert event_type=8, timestamp=0.386279, buffersize=79)
 > [  1.041621] (0:@) insert_into_buffer: inserted at 2
@@ -1201,7 +1203,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  1.254485] (0:@) insert_into_buffer: inserted at 46
 > [  1.254485] (0:@) new_pajeSubVariable: event_type=10, timestamp=1.254485
 > [  1.254485] (0:@) insert_into_buffer: insert event_type=10, timestamp=1.254485, buffersize=49)
-> [  1.254485] (0:@) insert_into_buffer: inserted at end
+> [  1.254485] (0:@) insert_into_buffer: inserted at end, pos = 49
 > [  1.254485] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.989430
 > [  1.254485] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.989430, buffersize=50)
 > [  1.254485] (0:@) insert_into_buffer: inserted at 47
@@ -1251,7 +1253,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  1.259775] (0:@) insert_into_buffer: inserted at end, pos = 64
 > [  1.259775] (0:@) new_pajeSubVariable: event_type=10, timestamp=1.259775
 > [  1.259775] (0:@) insert_into_buffer: insert event_type=10, timestamp=1.259775, buffersize=65)
-> [  1.259775] (0:@) insert_into_buffer: inserted at end
+> [  1.259775] (0:@) insert_into_buffer: inserted at end, pos = 65
 > [  1.259775] (0:@) new_pajeAddVariable: event_type=9, timestamp=1.254485
 > [  1.259775] (0:@) insert_into_buffer: insert event_type=9, timestamp=1.254485, buffersize=66)
 > [  1.259775] (0:@) insert_into_buffer: inserted at 65
@@ -1296,19 +1298,19 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  1.261939] (0:@) TRACE_paje_dump_buffer: ends
 > [  1.261939] (2:slave@Tremblay) new_pajeAddVariable: event_type=9, timestamp=1.261939
 > [  1.261939] (2:slave@Tremblay) insert_into_buffer: insert event_type=9, timestamp=1.261939, buffersize=78)
-> [  1.261939] (2:slave@Tremblay) insert_into_buffer: inserted at end
+> [  1.261939] (2:slave@Tremblay) insert_into_buffer: inserted at end, pos = 78
 > [  1.261939] (1:master@Tremblay) new_pajeSetVariable: event_type=8, timestamp=1.261939
 > [  1.261939] (1:master@Tremblay) insert_into_buffer: insert event_type=8, timestamp=1.261939, buffersize=79)
 > [  1.261939] (1:master@Tremblay) insert_into_buffer: inserted at end, pos = 79
 > [  1.557837] (0:@) new_pajeSetVariable: event_type=8, timestamp=0.526739
 > [  1.557837] (0:@) insert_into_buffer: insert event_type=8, timestamp=0.526739, buffersize=80)
-> [  1.557837] (0:@) insert_into_buffer: inserted at 0
+> [  1.557837] (0:@) insert_into_buffer: inserted at beginning
 > [  1.557837] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.526739
 > [  1.557837] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.526739, buffersize=81)
 > [  1.557837] (0:@) insert_into_buffer: inserted at 1
 > [  1.557837] (0:@) new_pajeSubVariable: event_type=10, timestamp=1.557837
 > [  1.557837] (0:@) insert_into_buffer: insert event_type=10, timestamp=1.557837, buffersize=82)
-> [  1.557837] (0:@) insert_into_buffer: inserted at end
+> [  1.557837] (0:@) insert_into_buffer: inserted at end, pos = 82
 > [  1.557837] (0:@) new_pajeSetVariable: event_type=8, timestamp=0.526739
 > [  1.557837] (0:@) insert_into_buffer: insert event_type=8, timestamp=0.526739, buffersize=83)
 > [  1.557837] (0:@) insert_into_buffer: inserted at 2
@@ -1403,7 +1405,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  1.644772] (0:@) insert_into_buffer: inserted at 14
 > [  1.644772] (0:@) new_pajeSubVariable: event_type=10, timestamp=1.644772
 > [  1.644772] (0:@) insert_into_buffer: insert event_type=10, timestamp=1.644772, buffersize=49)
-> [  1.644772] (0:@) insert_into_buffer: inserted at end
+> [  1.644772] (0:@) insert_into_buffer: inserted at end, pos = 49
 > [  1.644772] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.989430
 > [  1.644772] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.989430, buffersize=50)
 > [  1.644772] (0:@) insert_into_buffer: inserted at 15
@@ -1435,7 +1437,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  1.698296] (0:@) insert_into_buffer: inserted at end, pos = 58
 > [  1.698296] (0:@) new_pajeSubVariable: event_type=10, timestamp=1.698296
 > [  1.698296] (0:@) insert_into_buffer: insert event_type=10, timestamp=1.698296, buffersize=59)
-> [  1.698296] (0:@) insert_into_buffer: inserted at end
+> [  1.698296] (0:@) insert_into_buffer: inserted at end, pos = 59
 > [  1.698296] (0:@) new_pajeAddVariable: event_type=9, timestamp=1.644772
 > [  1.698296] (0:@) insert_into_buffer: insert event_type=9, timestamp=1.644772, buffersize=60)
 > [  1.698296] (0:@) insert_into_buffer: inserted at 59
@@ -1475,7 +1477,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  1.771649] (0:@) insert_into_buffer: inserted at end, pos = 70
 > [  1.771649] (0:@) new_pajeSubVariable: event_type=10, timestamp=1.771649
 > [  1.771649] (0:@) insert_into_buffer: insert event_type=10, timestamp=1.771649, buffersize=71)
-> [  1.771649] (0:@) insert_into_buffer: inserted at end
+> [  1.771649] (0:@) insert_into_buffer: inserted at end, pos = 71
 > [  1.771649] (0:@) new_pajeAddVariable: event_type=9, timestamp=1.698296
 > [  1.771649] (0:@) insert_into_buffer: insert event_type=9, timestamp=1.698296, buffersize=72)
 > [  1.771649] (0:@) insert_into_buffer: inserted at 71
@@ -1498,13 +1500,13 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  1.771649] (0:@) TRACE_paje_dump_buffer: ends
 > [  1.773709] (0:@) new_pajeSetVariable: event_type=8, timestamp=0.742611
 > [  1.773709] (0:@) insert_into_buffer: insert event_type=8, timestamp=0.742611, buffersize=78)
-> [  1.773709] (0:@) insert_into_buffer: inserted at 0
+> [  1.773709] (0:@) insert_into_buffer: inserted at beginning
 > [  1.773709] (0:@) new_pajeAddVariable: event_type=9, timestamp=0.742611
 > [  1.773709] (0:@) insert_into_buffer: insert event_type=9, timestamp=0.742611, buffersize=79)
 > [  1.773709] (0:@) insert_into_buffer: inserted at 1
 > [  1.773709] (0:@) new_pajeSubVariable: event_type=10, timestamp=1.773709
 > [  1.773709] (0:@) insert_into_buffer: insert event_type=10, timestamp=1.773709, buffersize=80)
-> [  1.773709] (0:@) insert_into_buffer: inserted at end
+> [  1.773709] (0:@) insert_into_buffer: inserted at end, pos = 80
 > [  1.773709] (0:@) new_pajeSetVariable: event_type=8, timestamp=0.742611
 > [  1.773709] (0:@) insert_into_buffer: insert event_type=8, timestamp=0.742611, buffersize=81)
 > [  1.773709] (0:@) insert_into_buffer: inserted at 2
@@ -1633,7 +1635,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  1.864258] (0:@) insert_into_buffer: inserted at end, pos = 38
 > [  1.864258] (0:@) new_pajeSubVariable: event_type=10, timestamp=1.864258
 > [  1.864258] (0:@) insert_into_buffer: insert event_type=10, timestamp=1.864258, buffersize=39)
-> [  1.864258] (0:@) insert_into_buffer: inserted at end
+> [  1.864258] (0:@) insert_into_buffer: inserted at end, pos = 39
 > [  1.864258] (0:@) new_pajeAddVariable: event_type=9, timestamp=1.773709
 > [  1.864258] (0:@) insert_into_buffer: insert event_type=9, timestamp=1.773709, buffersize=40)
 > [  1.864258] (0:@) insert_into_buffer: inserted at 39
@@ -1654,7 +1656,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  1.866422] (0:@) TRACE_paje_dump_buffer: ends
 > [  1.866422] (2:slave@Tremblay) new_pajeAddVariable: event_type=9, timestamp=1.866422
 > [  1.866422] (2:slave@Tremblay) insert_into_buffer: insert event_type=9, timestamp=1.866422, buffersize=44)
-> [  1.866422] (2:slave@Tremblay) insert_into_buffer: inserted at end
+> [  1.866422] (2:slave@Tremblay) insert_into_buffer: inserted at end, pos = 44
 > [  1.866422] (1:master@Tremblay) new_pajeSetVariable: event_type=8, timestamp=1.866422
 > [  1.866422] (1:master@Tremblay) insert_into_buffer: insert event_type=8, timestamp=1.866422, buffersize=45)
 > [  1.866422] (1:master@Tremblay) insert_into_buffer: inserted at end, pos = 45
@@ -1662,10 +1664,10 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  1.886758] (0:@) TRACE_paje_dump_buffer: ends
 > [  1.915117] (0:@) new_pajeAddVariable: event_type=9, timestamp=1.259775
 > [  1.915117] (0:@) insert_into_buffer: insert event_type=9, timestamp=1.259775, buffersize=46)
-> [  1.915117] (0:@) insert_into_buffer: inserted at 0
+> [  1.915117] (0:@) insert_into_buffer: inserted at beginning
 > [  1.915117] (0:@) new_pajeSubVariable: event_type=10, timestamp=1.915117
 > [  1.915117] (0:@) insert_into_buffer: insert event_type=10, timestamp=1.915117, buffersize=47)
-> [  1.915117] (0:@) insert_into_buffer: inserted at end
+> [  1.915117] (0:@) insert_into_buffer: inserted at end, pos = 47
 > [  1.915117] (0:@) new_pajeAddVariable: event_type=9, timestamp=1.259775
 > [  1.915117] (0:@) insert_into_buffer: insert event_type=9, timestamp=1.259775, buffersize=48)
 > [  1.915117] (0:@) insert_into_buffer: inserted at 1
@@ -1816,10 +1818,10 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  1.915117] (0:@) TRACE_paje_dump_buffer: ends
 > [  2.082294] (0:@) new_pajeAddVariable: event_type=9, timestamp=1.915117
 > [  2.082294] (0:@) insert_into_buffer: insert event_type=9, timestamp=1.915117, buffersize=50)
-> [  2.082294] (0:@) insert_into_buffer: inserted at end
+> [  2.082294] (0:@) insert_into_buffer: inserted at end, pos = 50
 > [  2.082294] (0:@) new_pajeSubVariable: event_type=10, timestamp=2.082294
 > [  2.082294] (0:@) insert_into_buffer: insert event_type=10, timestamp=2.082294, buffersize=51)
-> [  2.082294] (0:@) insert_into_buffer: inserted at end
+> [  2.082294] (0:@) insert_into_buffer: inserted at end, pos = 51
 > [  2.082294] (0:@) new_pajeAddVariable: event_type=9, timestamp=1.915117
 > [  2.082294] (0:@) insert_into_buffer: insert event_type=9, timestamp=1.915117, buffersize=52)
 > [  2.082294] (0:@) insert_into_buffer: inserted at 51
@@ -1922,10 +1924,10 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  2.102845] (0:@) TRACE_paje_dump_buffer: ends
 > [  2.300447] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.102845
 > [  2.300447] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.102845, buffersize=84)
-> [  2.300447] (0:@) insert_into_buffer: inserted at end
+> [  2.300447] (0:@) insert_into_buffer: inserted at end, pos = 84
 > [  2.300447] (0:@) new_pajeSubVariable: event_type=10, timestamp=2.300447
 > [  2.300447] (0:@) insert_into_buffer: insert event_type=10, timestamp=2.300447, buffersize=85)
-> [  2.300447] (0:@) insert_into_buffer: inserted at end
+> [  2.300447] (0:@) insert_into_buffer: inserted at end, pos = 85
 > [  2.300447] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.102845
 > [  2.300447] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.102845, buffersize=86)
 > [  2.300447] (0:@) insert_into_buffer: inserted at 85
@@ -2017,7 +2019,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  2.376132] (0:@) insert_into_buffer: inserted at end, pos = 114
 > [  2.376132] (0:@) new_pajeSubVariable: event_type=10, timestamp=2.376132
 > [  2.376132] (0:@) insert_into_buffer: insert event_type=10, timestamp=2.376132, buffersize=115)
-> [  2.376132] (0:@) insert_into_buffer: inserted at end
+> [  2.376132] (0:@) insert_into_buffer: inserted at end, pos = 115
 > [  2.376132] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.300447
 > [  2.376132] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.300447, buffersize=116)
 > [  2.376132] (0:@) insert_into_buffer: inserted at 115
@@ -2032,7 +2034,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  2.378296] (0:@) TRACE_paje_dump_buffer: ends
 > [  2.378296] (1:master@Tremblay) new_pajeSetVariable: event_type=8, timestamp=2.378296
 > [  2.378296] (1:master@Tremblay) insert_into_buffer: insert event_type=8, timestamp=2.378296, buffersize=118)
-> [  2.378296] (1:master@Tremblay) insert_into_buffer: inserted at end
+> [  2.378296] (1:master@Tremblay) insert_into_buffer: inserted at end, pos = 118
 > [  2.378296] (2:slave@Tremblay) new_pajeAddVariable: event_type=9, timestamp=2.378296
 > [  2.378296] (2:slave@Tremblay) insert_into_buffer: insert event_type=9, timestamp=2.378296, buffersize=119)
 > [  2.378296] (2:slave@Tremblay) insert_into_buffer: inserted at end, pos = 119
@@ -2041,7 +2043,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  2.519600] (0:@) insert_into_buffer: inserted at 18
 > [  2.519600] (0:@) new_pajeSubVariable: event_type=10, timestamp=2.519600
 > [  2.519600] (0:@) insert_into_buffer: insert event_type=10, timestamp=2.519600, buffersize=121)
-> [  2.519600] (0:@) insert_into_buffer: inserted at end
+> [  2.519600] (0:@) insert_into_buffer: inserted at end, pos = 121
 > [  2.519600] (0:@) new_pajeAddVariable: event_type=9, timestamp=1.864258
 > [  2.519600] (0:@) insert_into_buffer: insert event_type=9, timestamp=1.864258, buffersize=122)
 > [  2.519600] (0:@) insert_into_buffer: inserted at 19
@@ -2054,10 +2056,10 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  2.534800] (0:@) TRACE_paje_dump_buffer: ends
 > [  2.685562] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.534800
 > [  2.685562] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.534800, buffersize=124)
-> [  2.685562] (0:@) insert_into_buffer: inserted at end
+> [  2.685562] (0:@) insert_into_buffer: inserted at end, pos = 124
 > [  2.685562] (0:@) new_pajeSubVariable: event_type=10, timestamp=2.685562
 > [  2.685562] (0:@) insert_into_buffer: insert event_type=10, timestamp=2.685562, buffersize=125)
-> [  2.685562] (0:@) insert_into_buffer: inserted at end
+> [  2.685562] (0:@) insert_into_buffer: inserted at end, pos = 125
 > [  2.685562] (0:@) TRACE_paje_dump_buffer: dump until 1.698296. starts
 > [  2.685562] (0:@) TRACE_paje_dump_buffer: ends
 > [  2.685562] (1:master@Tremblay) new_pajeSetVariable: event_type=8, timestamp=2.685562
@@ -2080,10 +2082,10 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  2.685562] (0:@) insert_into_buffer: inserted at end, pos = 131
 > [  2.729394] (0:@) new_pajeAddVariable: event_type=9, timestamp=1.698296
 > [  2.729394] (0:@) insert_into_buffer: insert event_type=9, timestamp=1.698296, buffersize=132)
-> [  2.729394] (0:@) insert_into_buffer: inserted at 0
+> [  2.729394] (0:@) insert_into_buffer: inserted at beginning
 > [  2.729394] (0:@) new_pajeSubVariable: event_type=10, timestamp=2.729394
 > [  2.729394] (0:@) insert_into_buffer: insert event_type=10, timestamp=2.729394, buffersize=133)
-> [  2.729394] (0:@) insert_into_buffer: inserted at end
+> [  2.729394] (0:@) insert_into_buffer: inserted at end, pos = 133
 > [  2.729394] (0:@) new_pajeAddVariable: event_type=9, timestamp=1.698296
 > [  2.729394] (0:@) insert_into_buffer: insert event_type=9, timestamp=1.698296, buffersize=134)
 > [  2.729394] (0:@) insert_into_buffer: inserted at 1
@@ -2276,10 +2278,10 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  2.742626] (0:@) TRACE_paje_dump_buffer: ends
 > [  2.869854] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.742626
 > [  2.869854] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.742626, buffersize=46)
-> [  2.869854] (0:@) insert_into_buffer: inserted at end
+> [  2.869854] (0:@) insert_into_buffer: inserted at end, pos = 46
 > [  2.869854] (0:@) new_pajeSubVariable: event_type=10, timestamp=2.869854
 > [  2.869854] (0:@) insert_into_buffer: insert event_type=10, timestamp=2.869854, buffersize=47)
-> [  2.869854] (0:@) insert_into_buffer: inserted at end
+> [  2.869854] (0:@) insert_into_buffer: inserted at end, pos = 47
 > [  2.869854] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.742626
 > [  2.869854] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.742626, buffersize=48)
 > [  2.869854] (0:@) insert_into_buffer: inserted at 47
@@ -2317,7 +2319,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  2.888006] (0:@) insert_into_buffer: inserted at end, pos = 58
 > [  2.888006] (0:@) new_pajeSubVariable: event_type=10, timestamp=2.888006
 > [  2.888006] (0:@) insert_into_buffer: insert event_type=10, timestamp=2.888006, buffersize=59)
-> [  2.888006] (0:@) insert_into_buffer: inserted at end
+> [  2.888006] (0:@) insert_into_buffer: inserted at end, pos = 59
 > [  2.888006] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.869854
 > [  2.888006] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.869854, buffersize=60)
 > [  2.888006] (0:@) insert_into_buffer: inserted at 59
@@ -2332,7 +2334,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  2.890170] (0:@) TRACE_paje_dump_buffer: ends
 > [  2.890170] (1:master@Tremblay) new_pajeSetVariable: event_type=8, timestamp=2.890170
 > [  2.890170] (1:master@Tremblay) insert_into_buffer: insert event_type=8, timestamp=2.890170, buffersize=62)
-> [  2.890170] (1:master@Tremblay) insert_into_buffer: inserted at end
+> [  2.890170] (1:master@Tremblay) insert_into_buffer: inserted at end, pos = 62
 > [  2.890170] (2:slave@Tremblay) new_pajeAddVariable: event_type=9, timestamp=2.890170
 > [  2.890170] (2:slave@Tremblay) insert_into_buffer: insert event_type=9, timestamp=2.890170, buffersize=63)
 > [  2.890170] (2:slave@Tremblay) insert_into_buffer: inserted at end, pos = 63
@@ -2341,7 +2343,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  2.955790] (0:@) insert_into_buffer: inserted at 30
 > [  2.955790] (0:@) new_pajeSubVariable: event_type=10, timestamp=2.955790
 > [  2.955790] (0:@) insert_into_buffer: insert event_type=10, timestamp=2.955790, buffersize=65)
-> [  2.955790] (0:@) insert_into_buffer: inserted at end
+> [  2.955790] (0:@) insert_into_buffer: inserted at end, pos = 65
 > [  2.955790] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.300447
 > [  2.955790] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.300447, buffersize=66)
 > [  2.955790] (0:@) insert_into_buffer: inserted at 31
@@ -2354,10 +2356,10 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  2.976340] (0:@) TRACE_paje_dump_buffer: ends
 > [  3.113392] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.082294
 > [  3.113392] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.082294, buffersize=68)
-> [  3.113392] (0:@) insert_into_buffer: inserted at 0
+> [  3.113392] (0:@) insert_into_buffer: inserted at beginning
 > [  3.113392] (0:@) new_pajeSubVariable: event_type=10, timestamp=3.113392
 > [  3.113392] (0:@) insert_into_buffer: insert event_type=10, timestamp=3.113392, buffersize=69)
-> [  3.113392] (0:@) insert_into_buffer: inserted at end
+> [  3.113392] (0:@) insert_into_buffer: inserted at end, pos = 69
 > [  3.113392] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.082294
 > [  3.113392] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.082294, buffersize=70)
 > [  3.113392] (0:@) insert_into_buffer: inserted at 1
@@ -2507,7 +2509,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  3.173943] (0:@) insert_into_buffer: inserted at end, pos = 34
 > [  3.173943] (0:@) new_pajeSubVariable: event_type=10, timestamp=3.173943
 > [  3.173943] (0:@) insert_into_buffer: insert event_type=10, timestamp=3.173943, buffersize=35)
-> [  3.173943] (0:@) insert_into_buffer: inserted at end
+> [  3.173943] (0:@) insert_into_buffer: inserted at end, pos = 35
 > [  3.173943] (0:@) new_pajeAddVariable: event_type=9, timestamp=3.113392
 > [  3.173943] (0:@) insert_into_buffer: insert event_type=9, timestamp=3.113392, buffersize=36)
 > [  3.173943] (0:@) insert_into_buffer: inserted at 35
@@ -2562,10 +2564,10 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  3.194279] (0:@) TRACE_paje_dump_buffer: ends
 > [  3.340904] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.685562
 > [  3.340904] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.685562, buffersize=52)
-> [  3.340904] (0:@) insert_into_buffer: inserted at 0
+> [  3.340904] (0:@) insert_into_buffer: inserted at beginning
 > [  3.340904] (0:@) new_pajeSubVariable: event_type=10, timestamp=3.340904
 > [  3.340904] (0:@) insert_into_buffer: insert event_type=10, timestamp=3.340904, buffersize=53)
-> [  3.340904] (0:@) insert_into_buffer: inserted at end
+> [  3.340904] (0:@) insert_into_buffer: inserted at end, pos = 53
 > [  3.340904] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.685562
 > [  3.340904] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.685562, buffersize=54)
 > [  3.340904] (0:@) insert_into_buffer: inserted at 1
@@ -2695,7 +2697,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  3.389815] (0:@) insert_into_buffer: inserted at end, pos = 68
 > [  3.389815] (0:@) new_pajeSubVariable: event_type=10, timestamp=3.389815
 > [  3.389815] (0:@) insert_into_buffer: insert event_type=10, timestamp=3.389815, buffersize=69)
-> [  3.389815] (0:@) insert_into_buffer: inserted at end
+> [  3.389815] (0:@) insert_into_buffer: inserted at end, pos = 69
 > [  3.389815] (0:@) new_pajeAddVariable: event_type=9, timestamp=3.340904
 > [  3.389815] (0:@) insert_into_buffer: insert event_type=9, timestamp=3.340904, buffersize=70)
 > [  3.389815] (0:@) insert_into_buffer: inserted at 69
@@ -2804,7 +2806,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  3.399880] (0:@) insert_into_buffer: inserted at end, pos = 102
 > [  3.399880] (0:@) new_pajeSubVariable: event_type=10, timestamp=3.399880
 > [  3.399880] (0:@) insert_into_buffer: insert event_type=10, timestamp=3.399880, buffersize=103)
-> [  3.399880] (0:@) insert_into_buffer: inserted at end
+> [  3.399880] (0:@) insert_into_buffer: inserted at end, pos = 103
 > [  3.399880] (0:@) new_pajeAddVariable: event_type=9, timestamp=3.389815
 > [  3.399880] (0:@) insert_into_buffer: insert event_type=9, timestamp=3.389815, buffersize=104)
 > [  3.399880] (0:@) insert_into_buffer: inserted at 103
@@ -2822,7 +2824,7 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  3.829285] (0:@) insert_into_buffer: inserted at 40
 > [  3.829285] (0:@) new_pajeSubVariable: event_type=10, timestamp=3.829285
 > [  3.829285] (0:@) insert_into_buffer: insert event_type=10, timestamp=3.829285, buffersize=107)
-> [  3.829285] (0:@) insert_into_buffer: inserted at end
+> [  3.829285] (0:@) insert_into_buffer: inserted at end, pos = 107
 > [  3.829285] (0:@) new_pajeAddVariable: event_type=9, timestamp=3.173943
 > [  3.829285] (0:@) insert_into_buffer: insert event_type=9, timestamp=3.173943, buffersize=108)
 > [  3.829285] (0:@) insert_into_buffer: inserted at 41
@@ -2835,10 +2837,10 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  3.849836] (0:@) TRACE_paje_dump_buffer: ends
 > [  3.900952] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.869854
 > [  3.900952] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.869854, buffersize=110)
-> [  3.900952] (0:@) insert_into_buffer: inserted at 0
+> [  3.900952] (0:@) insert_into_buffer: inserted at beginning
 > [  3.900952] (0:@) new_pajeSubVariable: event_type=10, timestamp=3.900952
 > [  3.900952] (0:@) insert_into_buffer: insert event_type=10, timestamp=3.900952, buffersize=111)
-> [  3.900952] (0:@) insert_into_buffer: inserted at end
+> [  3.900952] (0:@) insert_into_buffer: inserted at end, pos = 111
 > [  3.900952] (0:@) new_pajeAddVariable: event_type=9, timestamp=2.869854
 > [  3.900952] (0:@) insert_into_buffer: insert event_type=9, timestamp=2.869854, buffersize=112)
 > [  3.900952] (0:@) insert_into_buffer: inserted at 1
@@ -3067,10 +3069,10 @@ $ $SG_TEST_EXENV ${bindir:=.}/tracing/ms$EXEEXT --cfg=tracing:1 --cfg=tracing/fi
 > [  3.914183] (0:@) TRACE_paje_dump_buffer: ends
 > [  4.420913] (0:@) new_pajeAddVariable: event_type=9, timestamp=3.389815
 > [  4.420913] (0:@) insert_into_buffer: insert event_type=9, timestamp=3.389815, buffersize=6)
-> [  4.420913] (0:@) insert_into_buffer: inserted at 0
+> [  4.420913] (0:@) insert_into_buffer: inserted at beginning
 > [  4.420913] (0:@) new_pajeSubVariable: event_type=10, timestamp=4.420913
 > [  4.420913] (0:@) insert_into_buffer: insert event_type=10, timestamp=4.420913, buffersize=7)
-> [  4.420913] (0:@) insert_into_buffer: inserted at end
+> [  4.420913] (0:@) insert_into_buffer: inserted at end, pos = 7
 > [  4.420913] (0:@) new_pajeAddVariable: event_type=9, timestamp=3.389815
 > [  4.420913] (0:@) insert_into_buffer: insert event_type=9, timestamp=3.389815, buffersize=8)
 > [  4.420913] (0:@) insert_into_buffer: inserted at 1