Ignore:
Timestamp:
Sep 6, 2019, 12:11:20 PM (6 years ago)
Author:
Joseph Pecoraro
Message:

Tail Deleted Frames shown in Web Inspector are sometimes incorrect (Shadow Chicken)
​https://bugs.webkit.org/show_bug.cgi?id=201366

Reviewed by Saam Barati.

Source/JavaScriptCore:

It is possible for the log buffer to be full right as someone is trying to
log a function prologue. In such a case the machine stack has already been
updated to include the new JavaScript call frame, but the prologue packet
cannot be included in the update because the log is full. This would mean
that the update fails to rationalize the machine stack with the shadow
log / stack. Namely, the current JavaScript call frame is unable to
find a matching prologue (the one we are holding to include after the update)
and inserts a questionable value into the stack; and in the process
missing and removing real potential tail calls.

For example:

"use strict";
function third() { return 1; }
function second() { return third(); }
function first() { return second(); }
function start() { return first(); }

If the the log fills up just as we are entering b then we may have a list
full log of packets looking like:

Shadow Log:

...
{ prologue-packet: entering start ... }
{ prologue-packet: entering first ... }
{ tail-packet: leaving first with a tail call }

Incoming Packet:

{ prologue-packet: entering second ... }

Current JS Stack:

second
start

Since the Current JavaScript stack already has second, if we process the
log without the prologue for second then we push a confused entry on the
shadow stack and clear the log such that we eventually lose the tail-call
information for first to second.

This patch solves this issue by providing enough extra space in the log
to always process the incoming packet when that forces an update. This way
clients can continue to behave exactly as they are.

--

We also document a corner case in some circumstances where the shadow
log may currently be insufficient to know how to reconcile:

For example:

"use strict";
function third() { return 1; }
function second() { return third(); }
function first() { return second(); }
function doNothingTail() { return Math.random() }
function start() {

for (i=0;i<1000;++i) doNothingTail();
return first();

}

In this case the ShadowChicken log may be processed multiple times due
to the many calls to doNothingTail / Math.random(). When calling the
Native function no prologue packet is emitted, so it is unclear that we
temporarly go deeper and come back out on the stack, so the log appears
to have lots of doNothingTail calls reusing the same frame:

Shadow Log:

...
, [123] {callee = 0x72a21aee0, frame = 0x7ffeef897270, callerFrame = 0x7ffeef8972e0, name = start}
, [124] {callee = 0x72a21af10, frame = 0x7ffeef8971f0, callerFrame = 0x7ffeef897270, name = doNothingTail}
, [125] tail-packet:{frame = 0x7ffeef8971f0}
, [126] {callee = 0x72a21af10, frame = 0x7ffeef8971f0, callerFrame = 0x7ffeef897270, name = doNothingTail}
, [127] tail-packet:{frame = 0x7ffeef8971f0}
...
, [140] {callee = 0x72a21af10, frame = 0x7ffeef8971f0, callerFrame = 0x7ffeef897270, name = doNothingTail}
, [141] tail-packet:{frame = 0x7ffeef8971f0}
, [142] {callee = 0x72a21af10, frame = 0x7ffeef8971f0, callerFrame = 0x7ffeef897270, name = doNothingTail}
, [143] tail-packet:{frame = 0x7ffeef8971f0}
, [144] {callee = 0x72a21aeb0, frame = 0x7ffeef8971f0, callerFrame = 0x7ffeef897270, name = first}
, [145] tail-packet:{frame = 0x7ffeef8971f0}
, [146] {callee = 0x72a21ae80, frame = 0x7ffeef8971f0, callerFrame = 0x7ffeef897270, name = second}
...

This log would seem to be indistinguishable from real tail recursion, such as:

"use strict";
function third() { return 1; }
function second() { return third(); }
function first() { return second(); }
function doNothingTail(n) {

return n ? doNothingTail(n-1) : first();

}
function start() {

return doNothingTail(1000);

}

Likewise there are more cases where the shadow log appears to be ambiguous with determining
the appropriate parent call frame with intermediate function calls. In practice this may
not be too problematic, as this is a best effort reconstruction of tail deleted frames.
It seems likely we would only show additional frames that did in fact happen serially
between JavaScript call frames, but may not actually be the proper parent frames
heirachy in the stack.

  • interpreter/ShadowChicken.cpp:

(JSC::ShadowChicken::Packet::dump const):
(JSC::ShadowChicken::Frame::dump const):
(JSC::ShadowChicken::dump const):
Improved debugging output. Especially for functions.

(JSC::ShadowChicken::ShadowChicken):
Make space in the log for 1 additional packet to process when we slow log.

(JSC::ShadowChicken::log):
Include this packet in our update.

(JSC::ShadowChicken::update):
Address an edge case where we can eliminate tail-deleted frames that don't make sense.

LayoutTests:

  • inspector/debugger/tail-deleted-frames-expected.txt: Removed.
  • inspector/debugger/tail-deleted-frames-from-vm-entry-expected.txt: Removed.
  • inspector/debugger/tail-deleted-frames-from-vm-entry.html: Removed.
  • inspector/debugger/tail-deleted-frames-this-value-expected.txt: Removed.
  • inspector/debugger/tail-deleted-frames-this-value.html: Removed.
  • inspector/debugger/tail-deleted-frames.html: Removed.

Remove legacy tests that are difficult to read.

  • inspector/debugger/tail-deleted-frames/resources/stack-trace-utilities.js: Added.

(TestPage.registerInitializer.window.getAsyncStackTrace):
(TestPage.registerInitializer.async.logThisObject):
(TestPage.registerInitializer.async.logScope):
(TestPage.registerInitializer.async.logCallFrame):
(TestPage.registerInitializer):

  • inspector/debugger/tail-deleted-frames/resources/tail-deleted-frames-intermediate-frames.js: Added.
  • inspector/debugger/tail-deleted-frames/resources/tail-deleted-frames-intermediate-native-tail-deleted-calls.js: Added.
  • inspector/debugger/tail-deleted-frames/resources/tail-deleted-frames-intermediate-tail-deleted-frames.js: Added.
  • inspector/debugger/tail-deleted-frames/resources/tail-deleted-frames-scopes.js: Added.
  • inspector/debugger/tail-deleted-frames/resources/tail-deleted-frames-this-value.js: Added.
  • inspector/debugger/tail-deleted-frames/resources/tail-deleted-frames-vm-entry.js: Added.
  • inspector/debugger/tail-deleted-frames/tail-deleted-frames-intermediate-frames-expected.txt: Added.
  • inspector/debugger/tail-deleted-frames/tail-deleted-frames-intermediate-frames.html: Added.
  • inspector/debugger/tail-deleted-frames/tail-deleted-frames-intermediate-tail-deleted-frames-expected.txt: Added.
  • inspector/debugger/tail-deleted-frames/tail-deleted-frames-intermediate-tail-deleted-frames.html: Added.
  • inspector/debugger/tail-deleted-frames/tail-deleted-frames-scopes-expected.txt: Added.
  • inspector/debugger/tail-deleted-frames/tail-deleted-frames-scopes.html: Added.
  • inspector/debugger/tail-deleted-frames/tail-deleted-frames-this-value-expected.txt: Added.
  • inspector/debugger/tail-deleted-frames/tail-deleted-frames-this-value.html: Added.
  • inspector/debugger/tail-deleted-frames/tail-deleted-frames-vm-entry-expected.txt: Added.
  • inspector/debugger/tail-deleted-frames/tail-deleted-frames-vm-entry.html: Added.

Include modern tests that are easier to read.

  • inspector/debugger/tail-deleted-frames/tail-deleted-frames-intermediate-native-tail-deleted-calls-expected.txt: Added.
  • inspector/debugger/tail-deleted-frames/tail-deleted-frames-intermediate-native-tail-deleted-calls.html: Added.

Include a test that is known to produce bad output, since we have reproductive steps.

  • platform/mac/TestExpectations:

Updated pathes.

File:
1 edited

Legend:

Unmodified
Added
Removed

  • trunk/Source/JavaScriptCore/interpreter/ShadowChicken.cpp

    r249577 r249586  
    4646   
    4747    if (isPrologue()) {
     48        String name = "?"_s;
     49        if (auto* function = jsDynamicCast<JSFunction*>(callee->vm(), callee)) {
     50            name = function->name(callee->vm());
     51            if (name.isEmpty())
     52                name = "?"_s;
     53        }
     54
    4855        out.print(
    4956            "{callee = ", RawPointer(callee), ", frame = ", RawPointer(frame), ", callerFrame = ",
    50             RawPointer(callerFrame), "}");
     57            RawPointer(callerFrame), ", name = ", name, "}");
    5158        return;
    5259    }
    … …  
    6370void ShadowChicken::Frame::dump(PrintStream& out) const
    6471{
     72    String name = "?"_s;
     73    if (auto* function = jsDynamicCast<JSFunction*>(callee->vm(), callee)) {
     74        name = function->name(callee->vm());
     75        if (name.isEmpty())
     76            name = "?"_s;
     77    }
     78
    6579    out.print(
    66         "{callee = ", RawPointer(callee), ", frame = ", RawPointer(frame), ", isTailDeleted = ",
    67         isTailDeleted, "}");
     80        "{callee = ", *callee, ", frame = ", RawPointer(frame), ", isTailDeleted = ",
     81        isTailDeleted, ", name = ", name, "}");
    6882}
    6983
    … …  
    7185    : m_logSize(Options::shadowChickenLogSize())
    7286{
    73     m_log = static_cast<Packet*>(fastZeroedMalloc(sizeof(Packet) * m_logSize));
     87    // Allow one additional packet beyond m_logEnd. This is useful for the moment we
     88    // log a packet when the log is full and force an update. At that moment the packet
     89    // that is being logged should be included in the update because it may be
     90    // a critical prologue needed to rationalize the current machine stack with the
     91    // shadow stack.
     92    m_log = static_cast<Packet*>(fastZeroedMalloc(sizeof(Packet) * (m_logSize + 1)));
    7493    m_logCursor = m_log;
    7594    m_logEnd = m_log + m_logSize;
    … …  
    83102void ShadowChicken::log(VM& vm, ExecState* exec, const Packet& packet)
    84103{
     104    // This write is allowed because we construct the log with space for 1 additional packet.
     105    *m_logCursor++ = packet;
    85106    update(vm, exec);
    86     *m_logCursor++ = packet;
    87107}
    88108
    … …  
    143163    }
    144164
    145    
    146165    if (ShadowChickenInternal::verbose)
    147166        dataLog("    Revised stack: ", listDump(m_stack), "\n");
    … …  
    289308
    290309            CallFrame* callFrame = visitor->callFrame();
    291             if (ShadowChickenInternal::verbose)
    292                 dataLog("    Examining ", RawPointer(callFrame), "\n");
     310            if (ShadowChickenInternal::verbose) {
     311                dataLog("    Examining callFrame:", RawPointer(callFrame), ", callee:", RawPointer(callFrame->jsCallee()), ", callerFrame:", RawPointer(callFrame->callerFrame()), "\n");
     312                JSObject* callee = callFrame->jsCallee();
     313                if (auto* function = jsDynamicCast<JSFunction*>(callee->vm(), callee))
     314                    dataLog("      Function = ", function->name(callee->vm()), "\n");
     315            }
     316
    293317            if (callFrame == highestPointSinceLastTime) {
    294318                if (ShadowChickenInternal::verbose)
    295                     dataLog("    Bailing at ", RawPointer(callFrame), " because it's the highest point since last time.\n");
     319                    dataLog("    Bailing at ", RawPointer(callFrame), " because it's the highest point since last time\n");
     320
     321                // FIXME: At this point the shadow stack may still have tail deleted frames
     322                // that do not run into the current call frame but are left in the shadow stack.
     323                // Those tail deleted frames should be validated somehow.
     324
    296325                return StackVisitor::Done;
    297326            }
    … …  
    319348                && m_log[indexInLog].frame == toPush.last().frame) {
    320349                if (ShadowChickenInternal::verbose)
    321                     dataLog("    Going to loop through to find tail deleted frames with indexInLog = ", indexInLog, " and push-stack top = ", toPush.last(), "\n");
     350                    dataLog("    Going to loop through to find tail deleted frames using ", RawPointer(callFrame), " with indexInLog = ", indexInLog, " and push-stack top = ", toPush.last(), "\n");
    322351                for (;;) {
    323352                    ASSERT(m_log[indexInLog].frame == toPush.last().frame);
    … …  
    341370                    }
    342371                    indexInLog--; // Skip over the tail packet.
     372
     373                    // FIXME: After a few iterations the tail packet referenced frame may not be the
     374                    // same as the original callFrame for the real stack frame we started with.
     375                    // It is unclear when we should break.
    343376                   
    344377                    if (!advanceIndexInLogTo(tailPacket.frame, nullptr, nullptr)) {
    … …  
    380413
    381414    if (ShadowChickenInternal::verbose)
    382         dataLog("    After pushing: ", *this, "\n");
     415        dataLog("    After pushing: ", listDump(m_stack), "\n");
    383416
    384417    // Remove tail frames until the number of tail deleted frames is small enough.
    … …  
    448481    out.print("\n");
    449482    for (unsigned i = 0; i < limit; ++i)
    450         out.print("\t", comma, m_log[i], "\n");
     483        out.print("\t", comma, "[", i, "] ", m_log[i], "\n");
    451484    out.print("]}");
    452485}
Note: See TracChangeset for help on using the changeset viewer.