Opened 6 years ago

Closed 5 years ago

Last modified 4 years ago

#8309 closed bug (fixed)

traceEvent truncates to 512 bytes

Reported by: duncan Owned by:
Priority: normal Milestone: 8.0.1
Component: Runtime System Version: 7.6.3
Keywords: eventlog tracing Cc: simonmar
Operating System: Unknown/Multiple Architecture: Unknown/Multiple
Type of failure: None/Unknown Test Case:
Blocked By: Blocking:
Related Tickets: #3874 Differential Rev(s): Phab:D656
Wiki Page:

Description

The Debug.Trace.traceEvent (& traceEventIO) use a code path that unnecessarily uses printf format strings and uses a fixed size 512-byte buffer, hence truncating all user trace messages at that size.

Here is the call path:

  • Debug.Trace.traceEvent (& traceEventIO) call traceEvent# primop
  • cmm impl of the primop stg_traceEventzh calls C RTS function traceUserMsg
  • traceUserMsg calls traceFormatUserMsg(cap, "%s", msg);, using the printf format string
  • traceFormatUserMsg uses postUserMsg which eventually calls postLogMsg
  • postLogMsg does the printf stuff

Here's what postLogMsg does:

#define BUF 512

void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap)
{
    char buf[BUF];
    nat size;

    size = vsnprintf(buf,BUF,msg,ap);
    if (size > BUF) {
        buf[BUF-1] = '\0';
        size = BUF;
    }

   ....

This is obviously designed for RTS-internal users, not the user path.

So the problem starts with this bit:

void traceUserMsg(Capability *cap, char *msg)
{
    traceFormatUserMsg(cap, "%s", msg);
}

It just should not use that code path. It should call something that directly posts the message, without any silly printf strings. In fact, the code path from the primop down should really be changed to use an explicit given length, rather than using a null-terminated string and having to call strlen.

Change History (6)

comment:1 Changed 6 years ago by edsko

subscribe

comment:2 Changed 5 years ago by thomie

Cc: simonmar added
Differential Rev(s): Phab:D656
Status: newpatch

I made traceUserMsg call postUserMarker (renamed to postUserEvent), which does not have the truncation problem.

See the commit message in Trac #9395 (d360d440) for a discussion about using null-terminated strings vs strings with an explicit length. I did not make any change here.

comment:3 Changed 5 years ago by Austin Seipp <austin@…>

In a82364c9410d35fa9cb5031d553212267c3628c5/ghc:

Don't truncate traceEvents to 512 bytes (#8309)

Summary:
Don't call postLogMsg to post a user msg, because it truncates messages to
512 bytes.

Rename traceCap_stderr and trace_stderr to vtraceCap_stderr and trace_stderr,
to signal that they take a va_list (similar to vdebugBelch vs debugBelch).

See #3874 for the original reason behind traceFormatUserMsg.

See the commit msg in #9395 (d360d440) for a discussion about using
null-terminated strings vs strings with an explicit length.

Test Plan:
Run `cabal install ghc-events` and inspect the result of `ghc-events show` on
an eventlog file created with `ghc -eventlog Test.hs` and `./Test +RTS -l`,
where Test.hs contains:

```
import Debug.Trace
main = traceEvent (replicate 510 'a' ++ "bcd") $ return ()
```

Depends on D655.

Reviewers: austin

Reviewed By: austin

Subscribers: thomie

Differential Revision: https://phabricator.haskell.org/D656

GHC Trac Issues: #8309

comment:4 Changed 5 years ago by thoughtpolice

Milestone: 7.12.1

Merged, thanks!

comment:5 Changed 5 years ago by thoughtpolice

Resolution: fixed
Status: patchclosed

comment:6 Changed 4 years ago by thoughtpolice

Milestone: 7.12.18.0.1

Milestone renamed

Note: See TracTickets for help on using tickets.