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.
Unified · Split
| @@ -171,6 +171,13 @@ void stats_global_query(struct mpv_global *global, struct mpv_node *out) · 170 unmodified lines | ||
| 171 | 171 | e->val_d = 0; |
| 172 | 172 | break; |
| 173 | 173 | case VAL_TIME: { |
| 174 | + if (e->time_start_ns) { // ongoing. effectively do end+start | |
| 175 | + e->val_rt += now - e->time_start_ns; | |
| 176 | + e->time_start_ns = now; | |
| 177 | + int64_t t = mp_thread_cpu_time_ns(e->thread_id); | |
| 178 | + e->val_th += t - e->cpu_start_ns; | |
| 179 | + e->cpu_start_ns = t; | |
| 180 | + } | |
| 174 | 181 | double t_cpu = MP_TIME_NS_TO_MS(e->val_th); |
| 175 | 182 | if (e->cpu_start_ns >= 0) |
| 176 | 183 | add_stat(out, e, "cpu", t_cpu, mp_tprintf(80, "%.2f ms", t_cpu)); |
| @@ -273,7 +280,9 @@ void stats_time_start(struct stats_ctx *ctx, const char *name) · 96 unmodified lines | ||
| 273 | 280 | return; |
| 274 | 281 | mp_mutex_lock(&ctx->base->lock); |
| 275 | 282 | struct stat_entry *e = find_entry(ctx, name); |
| 276 | − e->cpu_start_ns = mp_thread_cpu_time_ns(mp_thread_current_id()); | |
| 283 | + e->type = VAL_TIME; | |
| 284 | + e->thread_id = mp_thread_current_id(); | |
| 285 | + e->cpu_start_ns = mp_thread_cpu_time_ns(e->thread_id); | |
| 277 | 286 | e->time_start_ns = mp_time_ns(); |
| 278 | 287 | mp_mutex_unlock(&ctx->base->lock); |
| 279 | 288 | } |
| @@ -285,10 +294,9 @@ void stats_time_end(struct stats_ctx *ctx, const char *name) · 5 unmodified lines | ||
| 285 | 294 | return; |
| 286 | 295 | mp_mutex_lock(&ctx->base->lock); |
| 287 | 296 | struct stat_entry *e = find_entry(ctx, name); |
| 288 | − if (e->time_start_ns) { | |
| 289 | − e->type = VAL_TIME; | |
| 297 | + if (e->type == VAL_TIME && e->time_start_ns) { | |
| 290 | 298 | e->val_rt += mp_time_ns() - e->time_start_ns; |
| 291 | − e->val_th += mp_thread_cpu_time_ns(mp_thread_current_id()) - e->cpu_start_ns; | |
| 299 | + e->val_th += mp_thread_cpu_time_ns(e->thread_id) - e->cpu_start_ns; | |
| 292 | 300 | e->time_start_ns = 0; |
| 293 | 301 | } |
| 294 | 302 | mp_mutex_unlock(&ctx->base->lock); |