Tcl Source Code

View Ticket
Login
Ticket UUID: 2995655
Title: Report inner contexts in [info errorstack]
Type: Patch Version: None
Submitter: ferrieux Created on: 2010-05-02 23:24:04
Subsystem: None Assigned To: msofer
Priority: 9 Immediate Severity:
Status: Closed Last Modified: 2012-05-27 05:07:43
Resolution: Accepted Closed By: ferrieux
    Closed on: 2012-05-26 22:07:43
Description:
In TIP #348, now accepted and committed, the error stack reports a list of argslists for procedure calls, along with uplevel offsets.
However, it has been noted that the deepest argslist, aka the "inner context", ie the bytecode instruction and the arguments it used off the stack before deciding to raise an error, are not reported. This is frustrating, typically when [expr] with a complex expression raises an error like "domain error: argument not in valid range".

The attached patch, designed after advice from Miguel, overcomes this limitation by inserting (when possible) at the beginning of the errorstack:

    INNER {name_of_instruction arg1 arg2 ... argN}

for example:

    % proc f {x y} {expr {log($x)+acos($y)}}
    % f 1 2
    domain error: argument not in valid range
    % info errorstack
     INNER {invokeStk1 tcl::mathfunc::acos 2} CALL {f 1 2}

A few notes on the implementation:
(1) the impact on TEBC is intentionally minimal (gentle arm twisting, Mig ;-): a single line, saving the pc in another local.
(2) only those INSTs where the argc is readily computable, generate a nontrivial inner context report. Others are untouched, just like non-TEBC error sites.
(3) the 'knowledge base' giving the algorithm for counting the argc is a single switch() block mimicking a tiny part of TEBC, but which can evolve much slower, since the default is to report only the instruction name. Hence no need to 'keep in sync' too tightly. This should free the mind of those who want to innovate in TEBC...
(4) at this stage, there's room for optimization, like pre-computing and sharing the instruction-name literals, and also reusing the list storage for the inner context, just like was done for the error stack itself.

High prio because it is an extension that has been asked for during the TIP discussion, the TIP is very young, and a milestone release is approaching...
User Comments: ferrieux added on 2012-05-27 05:07:43:
Sure ! I forgot to close it...
Was committed on 2010-10-20 
[14d357357c]

dkf added on 2012-05-27 02:59:30:
So... is this now something that should be closed?

ferrieux added on 2010-10-21 03:54:03:
Thanks. Committed.

msofer added on 2010-10-21 03:31:30:
Go ahead - trying to guess wtf is happening with tebc timings is a losing proposition, let's leave it for some other time :P

ferrieux added on 2010-10-18 03:32:05:

File Added - 390221: inner9c.patch

ferrieux added on 2010-10-18 03:03:37:

File Added - 390220: inner9b.patch

ferrieux added on 2010-10-16 02:47:13:
Attaching timings, based on denoised tclbench output.
Bottom line: latest patch solves the perf issue of previous ones.
Still one pair of outliers (ARRAY genKeys) at 12%, but the modified part is not called in the timed part, so the effect is one of cache aligment/associativity or modified inter-function offset (could possibly be beaten by rearranging functions or adding a properly placed spacer).
Asking for permission to commit.

ferrieux added on 2010-10-16 02:41:36:

File Added - 390082: all.res

ferrieux added on 2010-10-13 06:30:19:

File Added - 389785: inner9.patch

ferrieux added on 2010-10-13 06:29:15:
Extensive benchmarking revealed a 18% slowdown on bench "DATA access in alist", which is TEBC-intensive.
Investigation showed that the proposed approach of an extra local or BottomData field in TEBCresume is the culprit; its update at each and every instruction is simply too costly.

Following your instructions, here is inner9.patch which takes the more conservative approach of NOT touching TEBCresume at all on the non-error path. The key is to extend GetSrcInfoForPc so that it is able to extract the beginning of the current instruction by crawling the bytecode. This crawling is short most of the time since it starts from the beginning of the current *command* when possible. Only in exceptional cases like constant expr trees, does it start from the beginning of the BC for lack of a command.

Timings soon.

ferrieux added on 2010-10-10 05:35:06:
Attaching inner8.patch which has two perf improvements:
  - no unnecessary alloc of a list for the inner context's argslist, thanks to the reuse of a cached list when unshared
  - no unnecessary alloc of an inst's name, nor table of such Tcl_Objs, through a dedicated new objtype (InstNames)
Bottom line: on the critical path, NO allocations except Tcl_Objs are done by the inner context extractor.

ferrieux added on 2010-10-10 05:31:18:

File Added - 389422: inner8.patch

ferrieux added on 2010-10-05 06:06:02:

File Added - 388841: inner7.patch

ferrieux added on 2010-09-30 04:51:19:

File Added - 388351: inner6.patch

ferrieux added on 2010-09-30 04:49:29:
OK, you made it all clear in one sentence: with saner NRE, TEBC is no longer a long-lived while(1)...switch(*pc), but rather a TEBCresume callback that gets re-pushed forever doing switch(*pc). Neat !
As a result, please find attached as inner6.patch the corrected inner context patch. Outline:
  - pcBeg is now a field in BP as per your suggestion
  - it is directly initialised to pc at beginning of TEBCresume (and to codeStart at beginning of TnrEBC)
  - it is directly used in the TclLogCommandInfo call
  - no more extra local :)
Test suite okay.

Now re the coro warning, it seems to cross the coro bottom correctly, up into the resume's caller stack, just as before (after you fixed the wub crash). Moreover, we see that [info level $n] doesn't cross the coro bottom:

% proc c x {yield;stack;error BEUH:$x}
% coroutine C c bla
% proc stack {} {catch {for {set n 0} {1} {incr n -1} {puts "LEVEL $n: [info level $n]"}}}
% proc f x {g $x}
% proc g x C
% f 2
LEVEL 0: stack
LEVEL -1: c bla
BEUH:bla
% info errorstack
INNER {returnStk BEUH:bla} CALL {c bla} CALL {g 2} CALL {f 2}

msofer added on 2010-09-29 05:29:06:
Mmhhh ... is this in coroutines? We stopped insuring that the framePtr chains can be traversed across the coroutine's bottom. Please see what [info frame] does to patch the chain when it needs it: in InfoFrameCmd, tclCmdIL.c lines 1156ff

If the problem is *not* in coroutines, no idea: let's talk.

ferrieux added on 2010-09-29 04:38:43:
Yikes ! Saner NRE kicked pcBeg out of sync again :/
Will dive, but insight appreciated: how has the return-from-error path changed, to reach this effect ?

ferrieux added on 2010-09-28 04:15:08:
Patch updated to HEAD (saner NRE). Timings coming soon.

ferrieux added on 2010-09-28 04:14:17:

File Added - 388076: inner5.patch

ferrieux added on 2010-09-07 05:21:56:

File Added - 385825: inner4.patch

ferrieux added on 2010-09-07 05:20:54:
OK, problem solved,  helped by bug 3059758. The core of the issue was not the tosPtr, but rather the 'pc jitter' (jumping to the last byte of the INST). Solved by adding a local to TEBC, and keeping it in sync in NR_DATA_DIG.
Test suite OK.

ferrieux added on 2010-06-09 04:44:36:

File Added - 376597: inner3.patch

ferrieux added on 2010-06-09 04:43:40:
Some progress: looks like the 'abnormalReturn' target in TEBC is associated with situations where the stack pointer is rewound out of sync with the pc (when popping from a nonrecursive call). Attached inner3.patch has a few additional checks do detect that early. Simplest crashing case is opt-3.2, summarized below:

package require opt 0.4.6
set n $::tcl::OptDescN
catch {::tcl::OptKeyDelete $n}
catch {::tcl::OptParse {{-foo}} {-blah}}

I suspect that a single NR_DATA_DIG could do the job, but I'd appreciate guidance.

ferrieux added on 2010-06-08 06:39:46:

File Added - 376494: inner2.patch

ferrieux added on 2010-06-08 06:39:20:

File Deleted - 376492:

ferrieux added on 2010-06-08 06:38:59:
Improved version now handles all sorts of compile-time, deferred errors.

Still crashing in the four following tests, to be investigated:

  namespace.test

  opt.test

  tcltest.test

  trace.test

ferrieux added on 2010-06-08 06:26:51:

File Added - 376492: inner2.patch

ferrieux added on 2010-05-10 05:08:27:

File Deleted - 372617:

ferrieux added on 2010-05-10 05:07:27:

File Added - 373398: inner.patch

ferrieux added on 2010-05-03 06:25:49:

File Added - 372617: inner.patch

Attachments: