#2047 various execution trace issues

[Vince Darley]

Under some circumstances, when idle events are
pending, execution traces with 'enterstep'
and 'leavestep' do not trace these events.

The attached script shows the problem. It runs two
different scenarios of tracing 'foo':

proc foo {} {
msg "hi"
set a 1
}

foo

after idle {puts idle} ; foo

The first of these works correctly, but the second
one skips three commands that should be traced --
these three events never occur:

{msg hi} 0 {} leavestep
{set a 1} enterstep
{set a 1} 0 1 leavestep

This is on Windows, but the code is entirely generic.

---
# script starts here

proc msg {txt} {
set a [::msgcat::mc $txt]
update idletasks
}

proc foo {} {
msg "hi"
set a 1
}

proc log {args} {
puts [string range $args 0 40]
}

trace add execution foo {enter leave enterstep
leavestep} log

puts stderr "tracing without any idletasks"
puts stderr "notice how there is a line '{msg hi} 0 {}
leavestep'"
update
foo

puts stderr "tracing with idletask"
after idle {puts idle} ; foo

puts stderr "Notice how in the second run, the
following lines"
puts stderr "are missing {
{msg hi} 0 {} leavestep
{set a 1} enterstep
{set a 1} 0 1 leavestep
}"

[Vince Darley]

script to illustrate bug

[Don Porter]

Logged In: YES
user_id=80530

the leavestep for [update idletasks] is missing too.

[Nobody/Anonymous]

Logged In: NO

I believe Hemang is looking into this one (could
someone perhaps add him as a maintainer to Tcl's
sourceforge project, so we can assign bugs to him?)

[Don Porter]

Logged In: YES
user_id=80530

I'm confused by TclTraceExecutionObjCmd().
It appears to call Tcl_TraceCommand to get
the basic job done, passing it flags like
TCL_TRACE_ENTER_EXEC.

However, Tcl_TraceCommand is documented
to accept only the flags TCL_TRACE_RENAME
or TCL_TRACE_DELETE. Is the documentation
just lagging behind?

The trace handler registered on line 3197 is
TraceCommandProc, and it appears to handle
only rename and delete traces.

What am I missing?

[Donal K. Fellows]

Logged In: YES
user_id=79902

The docs definitely need work. Whether or not that is the
only pending task in this area is another matter...

[Hemang Lavana]

Logged In: YES
user_id=81875

I looked into the code section questioned by DGP.
TclTraceExecutionObjCmd() calls Tcl_TraceCommand and passes
on execution flags to it as well as TraceCommandProc as its
trace handler. The Tcl_TraceCommand function has been
modified to register the execution flags. However, this is
not correct since such changes were not mentioned in tip62.
Also, the current trace handler is completely ignored --
correct trace handler should have been TraceExecutionProc
whose call is hard-coded in TclCheckExecutionTraces.

I will create a patch soon for fixing the above problems:
the changes made to Tcl_TraceCommand, Tcl_UntraceCommand and
Tcl_CommandTraceInfo for execution traces should be moved
into new internal functions. Moreover a new tip will be
required to expose the functionality of execution traces as
C APIs: Tcl_TraceExecution, Tcl_UntraceExecution, and
Tcl_ExecutionTraceInfo.

Next, I have created a patch for the original problem
submitted here. It includes fixes to tclCmdMZ.c file and a
shorter script to reproduce the problem as a testcase in
trace.test. I am including the patch here since the upload
button doesn't show up in my browser:

Index: generic/tclCmdMZ.c

RCS file: /cvsroot/tcl/tcl/generic/tclCmdMZ.c,v
retrieving revision 1.76
diff -r1.76 tclCmdMZ.c
49c49,54
< int startLevel; /* Used for bookkeeping
with execution traces */
---
> int startLevel; /* Used for bookkeeping
with step execution
> * traces, store the level
at which the step
> * trace was invoked */
> char *startCmd; /* Used for bookkeeping
with step execution
> * traces, store the
command name which invoked
> * step trace */
3189a3195
> tcmdPtr->startCmd = NULL;
3238a3245,3247
> if (tcmdPtr->startCmd != NULL) {
> ckfree((char
*)tcmdPtr->startCmd);
> }
3390a3400
> tcmdPtr->startCmd = NULL;
3965a3976,3978
> if (tcmdPtr->startCmd != NULL) {
> ckfree((char *)tcmdPtr->startCmd);
> }
4292c4305,4306
< * created an interpreter trace, we remove it
---
> * created an interpreter trace for enterstep and/or
leavestep
> * execution traces, we remove it here.
4295c4309,4310
< if ((tcmdPtr->stepTrace != NULL) && (level ==
tcmdPtr->startLevel)) {
---
> if ((tcmdPtr->stepTrace != NULL) && (level ==
tcmdPtr->startLevel)
> && (strcmp(command, tcmdPtr->startCmd) ==
0)) {
4297a4313,4315
> if (tcmdPtr->startCmd != NULL) {
> ckfree((char *)tcmdPtr->startCmd);
> }
4299d4316
<
4384,4385c4401,4406
< * Third, create an interpreter trace, if we need
one for
< * subsequent internal execution traces.
---
> * Third, if there are any step execution traces for
this proc,
> * we register an interpreter trace to invoke
enterstep and/or
> * leavestep traces.
> * We also need to save the current stack level and
the proc
> * string in startLevel and startCmd so that we
can delete this
> * interpreter trace when it reaches the end of
this proc.
4389a4411,4413
> tcmdPtr->startCmd =
> (char *) ckalloc((unsigned)
(strlen(command) + 1));
> strcpy(tcmdPtr->startCmd, command);
4398a4423,4425
> if (tcmdPtr->startCmd != NULL) {
> ckfree((char *)tcmdPtr->startCmd);
> }
Index: tests/trace.test
===================================================================
RCS file: /cvsroot/tcl/tcl/tests/trace.test,v
retrieving revision 1.22
diff -r1.22 trace.test
1840a1841,1870
> test trace-28.1 {enterstep and leavestep traces with
update idletasks (615043)} {
> catch {rename foo {}}
> proc foo {} {
> set a 1
> update idletasks
> set b 1
> }
>
> set info {}
> trace add execution foo {enter enterstep leavestep
leave} \ > [list traceExecute foo]
> update
> after idle {puts idle}
> foo
>
> trace remove execution foo {enter enterstep leavestep
leave} \ > [list traceExecute foo]
> rename foo {}
> join $info "\n"
> } {foo foo enter
> foo {set a 1} enterstep
> foo {set a 1} 0 1 leavestep
> foo {update idletasks} enterstep
> foo {puts idle} enterstep
> foo {puts idle} 0 {} leavestep
> foo {update idletasks} 0 {} leavestep
> foo {set b 1} enterstep
> foo {set b 1} 0 1 leavestep
> foo foo 0 1 leave}
>
1845a1876,1878
>
> # Unset the varaible when done
> catch {unset info}

[Don Porter]

Logged In: YES
user_id=80530

Thanks for looking into this.
Could you post the patch
to the Tcl Patch Tracker?

[Vince Darley]

Logged In: YES
user_id=32170

Attached the patch for Hemang.

[Vince Darley]

diff

[Hemang Lavana]

Logged In: YES
user_id=81875

I looked into the code section questioned by DGP.
TclTraceExecutionObjCmd() calls Tcl_TraceCommand and passes
on execution flags to it as well as TraceCommandProc as its
trace handler. The Tcl_TraceCommand function has been
modified to register the execution flags. However, this is
not correct since such changes were not mentioned in tip62.
Also, the current trace handler is completely ignored --
correct trace handler should have been TraceExecutionProc
whose call is hard-coded in TclCheckExecutionTraces.

I will create a patch soon for fixing the above problems:
the changes made to Tcl_TraceCommand, Tcl_UntraceCommand and
Tcl_CommandTraceInfo for execution traces should be moved
into new internal functions. Moreover a new tip will be
required to expose the functionality of execution traces as
C APIs: Tcl_TraceExecution, Tcl_UntraceExecution, and
Tcl_ExecutionTraceInfo.

Next, I have created a patch for the original problem
submitted here. It includes fixes to tclCmdMZ.c file and a
shorter script to reproduce the problem as a testcase in
trace.test. I am including the patch here since the upload
button doesn't show up in my browser:

Index: generic/tclCmdMZ.c

RCS file: /cvsroot/tcl/tcl/generic/tclCmdMZ.c,v
retrieving revision 1.76
diff -r1.76 tclCmdMZ.c
49c49,54
< int startLevel; /* Used for bookkeeping
with execution traces */
---
> int startLevel; /* Used for bookkeeping
with step execution
> * traces, store the level
at which the step
> * trace was invoked */
> char *startCmd; /* Used for bookkeeping
with step execution
> * traces, store the
command name which invoked
> * step trace */
3189a3195
> tcmdPtr->startCmd = NULL;
3238a3245,3247
> if (tcmdPtr->startCmd != NULL) {
> ckfree((char
*)tcmdPtr->startCmd);
> }
3390a3400
> tcmdPtr->startCmd = NULL;
3965a3976,3978
> if (tcmdPtr->startCmd != NULL) {
> ckfree((char *)tcmdPtr->startCmd);
> }
4292c4305,4306
< * created an interpreter trace, we remove it
---
> * created an interpreter trace for enterstep and/or
leavestep
> * execution traces, we remove it here.
4295c4309,4310
< if ((tcmdPtr->stepTrace != NULL) && (level ==
tcmdPtr->startLevel)) {
---
> if ((tcmdPtr->stepTrace != NULL) && (level ==
tcmdPtr->startLevel)
> && (strcmp(command, tcmdPtr->startCmd) ==
0)) {
4297a4313,4315
> if (tcmdPtr->startCmd != NULL) {
> ckfree((char *)tcmdPtr->startCmd);
> }
4299d4316
<
4384,4385c4401,4406
< * Third, create an interpreter trace, if we need
one for
< * subsequent internal execution traces.
---
> * Third, if there are any step execution traces for
this proc,
> * we register an interpreter trace to invoke
enterstep and/or
> * leavestep traces.
> * We also need to save the current stack level and
the proc
> * string in startLevel and startCmd so that we
can delete this
> * interpreter trace when it reaches the end of
this proc.
4389a4411,4413
> tcmdPtr->startCmd =
> (char *) ckalloc((unsigned)
(strlen(command) + 1));
> strcpy(tcmdPtr->startCmd, command);
4398a4423,4425
> if (tcmdPtr->startCmd != NULL) {
> ckfree((char *)tcmdPtr->startCmd);
> }
Index: tests/trace.test
===================================================================
RCS file: /cvsroot/tcl/tcl/tests/trace.test,v
retrieving revision 1.22
diff -r1.22 trace.test
1840a1841,1870
> test trace-28.1 {enterstep and leavestep traces with
update idletasks (615043)} {
> catch {rename foo {}}
> proc foo {} {
> set a 1
> update idletasks
> set b 1
> }
>
> set info {}
> trace add execution foo {enter enterstep leavestep
leave} \ > [list traceExecute foo]
> update
> after idle {puts idle}
> foo
>
> trace remove execution foo {enter enterstep leavestep
leave} \ > [list traceExecute foo]
> rename foo {}
> join $info "\n"
> } {foo foo enter
> foo {set a 1} enterstep
> foo {set a 1} 0 1 leavestep
> foo {update idletasks} enterstep
> foo {puts idle} enterstep
> foo {puts idle} 0 {} leavestep
> foo {update idletasks} 0 {} leavestep
> foo {set b 1} enterstep
> foo {set b 1} 0 1 leavestep
> foo foo 0 1 leave}
>
1845a1876,1878
>
> # Unset the varaible when done
> catch {unset info}

[Hemang Lavana]

Logged In: YES
user_id=81875

I created a patch [ 623143 ], but I see that Vince has
already attached the patch file here. So [ 623143 ] may be
closed.

[Vince Darley]

Logged In: YES
user_id=32170

I've committed Hemang's patch, but left this report
open with a different title, since Hemang indicates
below that there are further issues which ought to be
cleaned up in the future.

[Vince Darley]

Logged In: YES
user_id=32170

I've done the necessary cleanup, I believe, and will commit
asap.