Previously stats_time_start first sampled cpu-time and then real-time,
while stats_time_end sampled them in reverse order.
This resulted in real-time delta values being possibly a bit smaller
than the respective cpu-time deltas, which could become meaningful if
the start/end durations are consistently very short and very frequent.
In one test case (measuging the time spent at the event loop of
a script which spins on zero timeouts), this resulted in accumulated
real-time value of ~230ms per second, with a respective cpu-time
values of ~500ms. This should not be possible with single thread load.
Now start and end sample the values at the same order, so that it
balances on average. Each start/end delta now includes overhead of one
of each sample type, and excludes one of each sample type on average.
With the test case above, it's now 490 +-1 ms for both.
(the other 510ms real-time are at the excluded mpv_wait_event calls
and the unmeasured-overhead-parts of stats_time_start/end).
This fixes a bug where if stats reset happened after stats_time_start
and before stats_time_end, then the next reported cpu-time value of
that measurement was from the thread startup.
The long version:
stats resets the time-accumulated values if more than two seconds
ellapsed since last poll.
The reset keeps the elements, but makes them as if no measurement was
yet taken, so that they don't show up at new reports until a new
measurement is taken.
While the events and (untimed) cpu are reset, the timed-cpu value
was only partially reset - the values are reset but the indication
that the element is empty was not enough for stats_time_end.
So when reset happened between start/end calls, stats_time_end was
entered eventhough it shouldn't have, but with reset cpu-time value
it calculated the time since the thread's startup, hence this bug.
Further polls were ok, because they are of the delta since the
previous poll. But at the next reset it happened again.
Now the cpu-value is reset correctly, which fixes this bug.
stats_time_start and stats_time_end accumulate real-time and cpu-time
between these calls, but the total was only updated on stats_time_end.
This resulted in two issues:
- Inaccurate measured value if a report (read the perf-info property)
happened between start/end. No biggie because it's OK on average and
typically each start/end duration is quite smaller than the interval.
- If the start/end duration is bigger than the interval, then one or
more intervals had a report value (delta) of 0, and then one report
with a value bigger than the interval - which shouldn't be possible.
This commit effectively does end+start at the report time for ongoing
timed measurements, so that the report accounts for them too.
Doing end+start at the report required two more changes:
Store the element type (VAL_TIME) at stats_time_start rather than at
the end. Otherwise if the report happens after the first start but
before the first end, then the type is not yet set and the element
is skipped at the report (bypassing the end+start).
Store the thread id at the element. start/end measure the cpu-time at
the current thread so they used pthread_self(), but with the report
usually running on a different thread, it needs the thread id for the
measurement. Measuring cpu-time from a different thread is OK, and
already happens with VAL_THREAD_CPU_TIME elements during the report.
While at it, stats_time_end now uses the thread id which was stored on
start instead of using pthread_self(). This also serves as a general
protection against measuring start/end from different threads, which
would yield generally meaningless results anyway. In mpv all the
start/end calls for the same element are at the same thread.
On Windows and any other platform where cpu-time is unsuported,
previously the cpu-time was reported as 0, and now it's omitted
(at the perf-info property native value).
Code which process this report, like stats.lua, could not distinguish
between 0 which was due to unsupported platform, and "real" 0 which
indicates zero cpu activity in this poll-period.
In stats.lua this resulted in a whole lot of empty cpu graphs,
including one for every loaded script.
Now cpu-time is excluded from the report on unsupported platforms.
Real-time is obviously still being reported where requested.
Implementation wise, this is slightly hacky, by literally only
excluding the cpu-time nodes from the report itself, while keeping
all the other cpu-tinme code intact.
A more correct solution might be to identify support at compile
(configure) time, and no-op the relevant code if needed.
However, stats.c is already hacky in parts, and there's no real cost
to keeping the code active even if the result is excluded at the
report, and it's also way simpler and less bug prone. So be it.
This change essentially removes mp_thread_self() and instead add
mp_thread_id to track threads and have ability to query current thread
id during runtime.
This will be useful for upcoming win32 implementation, where accessing
thread handle is different than on pthreads. Greatly reduces complexity.
Otherweis locked map of tid <-> handle is required which is completely
unnecessary for all mpv use-cases.
Note that this is the mp_thread_id, not to confuse with system tid. For
example on threads-posix implementation it is simply pthread_t.
since i was going to fix the include order of stdatomic, might as well
sort the surrouding includes in accordance with the project's coding
style.
some headers can sometime require specific include order. standard
library headers usually don't. but mpv might "hack into" the standard
headers (e.g pthreads) so that complicates things a bit more.
hopefully nothing breaks. if it does, the style guide is to blame.
replace it with <stdatomic.h> and replace the mp_atomic_* typedefs with
explicit _Atomic qualified types.
also add missing config.h includes on some files.
Add an infrastructure for collecting performance-related data, use it in
some places. Add rendering of them to stats.lua.
There were two main goals: minimal impact on the normal code and normal
playback. So all these stats_* function calls either happen only during
initialization, or return immediately if no stats collection is going
on. That's why it does this lazily adding of stats entries etc. (a first
iteration made each stats entry an API thing, instead of just a single
stats_ctx, but I thought that was getting too intrusive in the "normal"
code, even if everything gets worse inside of stats.c).
You could get most of this information from various profilers (including
the extremely primitive --dump-stats thing in mpv), but this makes it
easier to see the most important information at once (at least in
theory), partially because we know best about the context of various
things.
Not very happy with this. It's all pretty primitive and dumb. At this
point I just wanted to get over with it, without necessarily having to
revisit it later, but with having my stupid statistics.
Somehow the code feels terrible. There are a lot of meh decisions in
there that could be better or worse (but mostly could be better), and it
just sucks but it's also trivial and uninteresting and does the job. I
guess I hate programming. It's so tedious and the result is always shit.
Anyway, enjoy.
Kacper Michajłow