// Shared instrumentation for the windowing demos (see features/f01-first-pixel.md
// § Instrumentation). Every demo logs one line per event to **stderr** in the
// format
//
// <monotonic_us> <DEMO> <EVENT_KIND> key=value ...
//
// where `<monotonic_us>` is microseconds since `instrInit` (core.time.MonoTime,
// so the clock is monotonic and immune to wall-clock jumps). stderr is chosen so
// the lines interleave with libwayland's `WAYLAND_DEBUG=1` protocol trace (also
// stderr) — the combined stream is the evidence the findings docs quote.
//
// This file is the canonical copy; other demo packages copy it verbatim.
// Everything is `nothrow @nogc` so event-loop callbacks (which platform shims
// commonly stamp `nothrow @nogc`, e.g. via ImportC `#pragma attribute`) can log
// without relaxing their attributes.
//
// Conventions:
// - `instrStep` is emitted immediately *after* the named API call returns, so
// the delta between consecutive `step` lines is the cost of the later call.
// - The mandatory event kinds are `init_start`, `step name=<api>`,
// `window_created`, `first_configure`, `first_pixel_presented`,
// `resize size=WxH scale=S`, `frame_callback t=..`, `close_requested`.
// Demos may add extra kinds (e.g. `configure serial=N size=WxH` for F02).
module (module) instrumentinstrument;
import (package) corecore.(package) core.stdcstdc.(module) core.stdc.stdioD header file for C99 <stdio.h>
pubs.opengroup.org/onlinepubs/009695399/basedefs/stdio.h.html, stdio.h
Source
core/stdc/stdio.d
stdio : (alias) instrument.fprintf = int core.stdc.stdio.fprintf(shared(core.stdc.stdio._IO_FILE)* stream, scope const(char*) format, scope const ...) nothrow @nogcfprintf, (alias) instrument.fputc = int core.stdc.stdio.fputc(int c, shared(core.stdc.stdio._IO_FILE)* stream) nothrow @nogc @trustedfputc, (alias shared global) instrument.stderr = shared(core.stdc.stdio._IO_FILE*) core.stdc.stdio.stderrstderr;
import (package) corecore.(module) core.timeModule containing core time functionality, such as Duration (which
represents a duration of time) or MonoTime (which represents a
timestamp of the system's monotonic clock).
Various functions take a string (or strings) to represent a unit of time
(e.g. convert!("days", "hours")(numDays)). The valid strings to use
with such functions are "years", "months", "weeks", "days", "hours",
"minutes", "seconds", "msecs" (milliseconds), "usecs" (microseconds),
"hnsecs" (hecto-nanoseconds - i.e. 100 ns) or some subset thereof. There
are a few functions that also allow "nsecs", but very little actually
has precision greater than hnsecs.
Symbol Description Types Duration Represents a duration of time of weeks or less (kept internally as hnsecs). (e.g. 22 days or 700 seconds). TickDuration DEPRECATED Represents a duration of time in system clock ticks, using the highest precision that the system provides. MonoTime Represents a monotonic timestamp in system clock ticks, using the highest precision that the system provides. Functions convert Generic way of converting between two time units. dur Allows constructing a Duration from the given time units with the given length. weeks days hours
minutes seconds msecs
usecs hnsecs nsecs |
Convenience aliases for dur. |
| abs | Returns the absolute value of a duration. |
From Duration
From TickDuration
From units
To Duration tickDuration.to, std,conv!Duration() dur!"msecs"(5) or 5.msecs()
| To TickDuration |
duration.to, std,conv!TickDuration() |
|
TickDuration.from!"msecs"(msecs) |
| To units |
duration.total!"days" |
tickDuration.msecs |
convert!("days", "msecs")(msecs) |
Source
core/time.d
time : (struct) core.time.MonoTimeImpl!(ClockType.normal)MonoTime;
nothrow @nogc @system:
private __gshared (struct) core.time.MonoTimeImpl!(ClockType.normal)MonoTime (__gshared global) @system core.time.MonoTimeImpl!(ClockType.normal) instrument.g_t0g_t0;
private __gshared const(char)* (__gshared global) @system const(char)* instrument.g_demog_demo = "demo";
/// Record the process epoch and emit `init_start`. Call first thing in `main`.
void void instrument.instrInit(const(char)* demoName) nothrow @nogc @systemRecord the process epoch and emit init_start. Call first thing in main.
instrInit(const(char)* (parameter) const(char)* demoNamedemoName)
{
(__gshared global) @system core.time.MonoTimeImpl!(ClockType.normal) instrument.g_t0g_t0 = (struct) core.time.MonoTimeImpl!(ClockType.normal)MonoTime.core.time.MonoTimeImpl!(ClockType.normal) core.time.MonoTimeImpl!(ClockType.normal).currTime() nothrow @nogc @property @trustedThe current time of the system's monotonic clock. This has no relation
to the wall clock time, as the wall clock time can be adjusted (e.g.
by NTP), whereas the monotonic clock always moves forward. The source
of the monotonic time is system-specific.
On Windows, QueryPerformanceCounter is used. On Mac OS X,
mach_absolute_time is used, while on other POSIX systems,
clock_gettime is used.
Warning: On some systems, the monotonic clock may stop counting
when the computer goes to sleep or hibernates. So, the
monotonic clock may indicate less time than has actually
passed if that occurs. This is known to happen on
Mac OS X. It has not been tested whether it occurs on
either Windows or Linux.
currTime;
(__gshared global) @system const(char)* instrument.g_demog_demo = (parameter) const(char)* demoNamedemoName;
void instrument.instrEvent!()(const(char)* kind, const(char)* fmt = null) nothrow @nogc @systemCore emitter: <monotonic_us> <DEMO> <kind> plus an optional
printf-formatted key=value ... tail.
instrEvent("init_start");
}
/// Microseconds elapsed since `instrInit` (the timestamp every line carries).
long long instrument.instrNowUs() nothrow @nogc @systemMicroseconds elapsed since instrInit (the timestamp every line carries).
instrNowUs()
{
return ((struct) core.time.MonoTimeImpl!(ClockType.normal)MonoTime.core.time.MonoTimeImpl!(ClockType.normal) core.time.MonoTimeImpl!(ClockType.normal).currTime() nothrow @nogc @property @trustedThe current time of the system's monotonic clock. This has no relation
to the wall clock time, as the wall clock time can be adjusted (e.g.
by NTP), whereas the monotonic clock always moves forward. The source
of the monotonic time is system-specific.
On Windows, QueryPerformanceCounter is used. On Mac OS X,
mach_absolute_time is used, while on other POSIX systems,
clock_gettime is used.
Warning: On some systems, the monotonic clock may stop counting
when the computer goes to sleep or hibernates. So, the
monotonic clock may indicate less time than has actually
passed if that occurs. This is known to happen on
Mac OS X. It has not been tested whether it occurs on
either Windows or Linux.
currTime - core.time.Duration core.time.MonoTimeImpl!(ClockType.normal).opBinary!"-"(core.time.MonoTimeImpl!(ClockType.normal) rhs) const pure nothrow @nogc @safeSubtracting two MonoTimes results in a Duration representing
the amount of time which elapsed between them.
The primary way that programs should time how long something takes is to
do
MonoTime before = MonoTime.currTime;
// do stuff
MonoTime after = MonoTime.currTime;
// How long it took.
Duration timeElapsed = after - before;
or to use a wrapper (such as a stop watch type) which does that.
Warning:
Because Duration is in hnsecs, whereas MonoTime is in system
ticks, it's usually the case that this assertion will fail
auto before = MonoTime.currTime;
// do stuff
auto after = MonoTime.currTime;
auto timeElapsed = after - before;
assert(before + timeElapsed == after);
This is generally fine, and by its very nature, converting from
system ticks to any type of seconds (hnsecs, nsecs, etc.) will
introduce rounding errors, but if code needs to avoid any of the
small rounding errors introduced by conversion, then it needs to use
MonoTime's ticks property and keep all calculations in ticks
rather than using Duration.
g_t0).long core.time.Duration.total!"usecs"() const pure nothrow @nogc @property @safeReturns the total number of the given units in this Duration.
So, unlike split, it does not strip out the larger units.
Examples
assert(dur!"weeks"(12).total!"weeks" == 12);
assert(dur!"weeks"(12).total!"days" == 84);
assert(dur!"days"(13).total!"weeks" == 1);
assert(dur!"days"(13).total!"days" == 13);
assert(dur!"hours"(49).total!"days" == 2);
assert(dur!"hours"(49).total!"hours" == 49);
assert(dur!"nsecs"(2007).total!"hnsecs" == 20);
assert(dur!"nsecs"(2007).total!"nsecs" == 2000);
total!"usecs";
}
/// Core emitter: `<monotonic_us> <DEMO> <kind>` plus an optional
/// printf-formatted `key=value ...` tail.
void void instrument.instrEvent!(const(char)*)(const(char)* kind, const(char)* fmt = null, const(char)* __param_2) nothrow @nogc @systemCore emitter: <monotonic_us> <DEMO> <kind> plus an optional
printf-formatted key=value ... tail.
instrEvent(Args...)(const(char)* (parameter) const(char)* kindkind, const(char)* (parameter) const(char)* fmtfmt = null, ArgsArgs (parameter) () argsargs)
{
int core.stdc.stdio.fprintf(shared(core.stdc.stdio._IO_FILE)* stream, scope const(char*) format, scope const ...) nothrow @nogcfprintf((shared global) shared(core.stdc.stdio._IO_FILE*) core.stdc.stdio.stderrstderr, "%lld %s %s", long instrument.instrNowUs() nothrow @nogc @systemMicroseconds elapsed since instrInit (the timestamp every line carries).
instrNowUs(), (__gshared global) @system const(char)* instrument.g_demog_demo, (parameter) const(char)* kindkind);
if ((parameter) const(char)* fmtfmt !is null)
{
int core.stdc.stdio.fputc(int c, shared(core.stdc.stdio._IO_FILE)* stream) nothrow @nogc @trustedfputc(' ', (shared global) shared(core.stdc.stdio._IO_FILE*) core.stdc.stdio.stderrstderr);
int core.stdc.stdio.fprintf(shared(core.stdc.stdio._IO_FILE)* stream, scope const(char*) format, scope const ...) nothrow @nogcfprintf((shared global) shared(core.stdc.stdio._IO_FILE*) core.stdc.stdio.stderrstderr, (parameter) const(char)* fmtfmt, args);
}
int core.stdc.stdio.fputc(int c, shared(core.stdc.stdio._IO_FILE)* stream) nothrow @nogc @trustedfputc('\n', (shared global) shared(core.stdc.stdio._IO_FILE*) core.stdc.stdio.stderrstderr);
}
/// One initialization API call completed (emit right after the call returns).
void void instrument.instrStep(const(char)* api) nothrow @nogc @systemOne initialization API call completed (emit right after the call returns).
instrStep(const(char)* (parameter) const(char)* apiapi)
{
void instrument.instrEvent!(const(char)*)(const(char)* kind, const(char)* fmt = null, const(char)* __param_2) nothrow @nogc @systemCore emitter: <monotonic_us> <DEMO> <kind> plus an optional
printf-formatted key=value ... tail.
instrEvent("step", "name=%s", (parameter) const(char)* apiapi);
}
/// All window objects exist client-side (nothing is on screen yet).
void void instrument.instrWindowCreated() nothrow @nogc @systemAll window objects exist client-side (nothing is on screen yet).
instrWindowCreated()
{
void instrument.instrEvent!()(const(char)* kind, const(char)* fmt = null) nothrow @nogc @systemCore emitter: <monotonic_us> <DEMO> <kind> plus an optional
printf-formatted key=value ... tail.
instrEvent("window_created");
}
/// The first server-driven configure/geometry negotiation completed.
void void instrument.instrFirstConfigure() nothrow @nogc @systemThe first server-driven configure/geometry negotiation completed.
instrFirstConfigure()
{
void instrument.instrEvent!()(const(char)* kind, const(char)* fmt = null) nothrow @nogc @systemCore emitter: <monotonic_us> <DEMO> <kind> plus an optional
printf-formatted key=value ... tail.
instrEvent("first_configure");
}
/// The platform confirmed the first software-drawn frame is presented.
void void instrument.instrFirstPixelPresented() nothrow @nogc @systemThe platform confirmed the first software-drawn frame is presented.
instrFirstPixelPresented()
{
void instrument.instrEvent!()(const(char)* kind, const(char)* fmt = null) nothrow @nogc @systemCore emitter: <monotonic_us> <DEMO> <kind> plus an optional
printf-formatted key=value ... tail.
instrEvent("first_pixel_presented");
}
/// The window size (and/or scale) changed.
void void instrument.instrResize(int width, int height, int scale) nothrow @nogc @systemThe window size (and/or scale) changed.
instrResize(int (parameter) int widthwidth, int (parameter) int heightheight, int (parameter) int scalescale)
{
void instrument.instrEvent!(int, int, int)(const(char)* kind, const(char)* fmt = null, int __param_2, int __param_3, int __param_4) nothrow @nogc @systemCore emitter: <monotonic_us> <DEMO> <kind> plus an optional
printf-formatted key=value ... tail.
instrEvent("resize", "size=%dx%d scale=%d", (parameter) int widthwidth, (parameter) int heightheight, (parameter) int scalescale);
}
/// A frame/vsync callback fired; `t` is the platform's presentation-time hint.
void void instrument.instrFrameCallback(uint t) nothrow @nogc @systemA frame/vsync callback fired; t is the platform's presentation-time hint.
instrFrameCallback(uint (parameter) uint tt)
{
void instrument.instrEvent!uint(const(char)* kind, const(char)* fmt = null, uint __param_2) nothrow @nogc @systemCore emitter: <monotonic_us> <DEMO> <kind> plus an optional
printf-formatted key=value ... tail.
instrEvent("frame_callback", "t=%u", (parameter) uint tt);
}
/// The user/compositor asked the window to close.
void void instrument.instrCloseRequested() nothrow @nogc @systemThe user/compositor asked the window to close.
instrCloseRequested()
{
void instrument.instrEvent!()(const(char)* kind, const(char)* fmt = null) nothrow @nogc @systemCore emitter: <monotonic_us> <DEMO> <kind> plus an optional
printf-formatted key=value ... tail.
instrEvent("close_requested");
}