Skip to content

webmachine_util: monotonic-time-aware now_diff helpers - #1

Merged
samwar merged 2 commits into
mainfrom
monotonic-time-diff-helpers
Jul 20, 2026
Merged

webmachine_util: monotonic-time-aware now_diff helpers#1
samwar merged 2 commits into
mainfrom
monotonic-time-diff-helpers

Conversation

@samwar

@samwar samwar commented Jul 20, 2026

Copy link
Copy Markdown
Member

Summary

Finishes migrating webmachine_util:now_diff_milliseconds/2 off os:timestamp() tuples and onto the erlang:monotonic_time() native-integer inputs the wm_log_data record has been carrying for a while. Adds a matching now_diff_microseconds/2 so downstream access-log handlers don't need to duplicate the conversion.

Motivation

The wm_log_data record's start_time, end_time, and finish_time fields were migrated from os:timestamp() tuples to erlang:monotonic_time() integers in native units. Internal callers (webmachine_access_log_handler, webmachine_perf_log_handler) followed suit and moved to the new webmachine_log:{request,post}_processing_time/1 helpers.

What got left behind was webmachine_util:now_diff_milliseconds/2 — still exported public API, still tuple-only:

now_diff_milliseconds({M,S,U}, {M,S1,U1}) ->
    ((S-S1) * 1000) + ((U-U1) div 1000);
now_diff_milliseconds({M,S,U}, {M1,S1,U1}) ->
    ((M-M1)*1000000+(S-S1))*1000 + ((U-U1) div 1000).

Any downstream consumer with its own gen_event handler that reads start_time/end_time off wm_log_data and diffs them via this function will hit no function clause matching now_diff_milliseconds(<neg-integer>, <neg-integer>) on every request.

Changes

  • now_diff_milliseconds/2 — replace tuple clauses with an integer-input path that delegates to erlang:convert_time_unit(Diff, native, millisecond). Undefined "later" time is treated as erlang:monotonic_time() — same convention webmachine_log:performance_time_diff/2 uses.
  • now_diff_microseconds/2 — new, matching shape. Matches the older timer:now_diff/2 return unit for consumers that log response times at microsecond granularity.
  • diff_native/2 — private helper factored out so both public functions share the same undefined-argument handling.
  • Eunit tests updated to construct start/end times as native-unit integers and cover both the millisecond and microsecond paths, plus the undefined branch on each.

Compatibility

Tuple callers will no longer match. In practice, no such callers should exist:

  • The record migration to native-unit integers means anyone reading start_time/end_time off the record has been passing integers to now_diff_milliseconds/2 since that migration and getting silent runtime crashes.
  • Internal webmachine callers all moved to webmachine_log:{request,post}_processing_time/1 in the same wave.

This PR turns silent breakage into an explicit signal to update.

Tests

Six eunit test functions cover the helpers. Two are new and address the specific coverage gap that let the tuple-based clauses stay green after the record migrated to native integers.

Existing coverage:

  • now_diff_milliseconds_test — synthetic integers, exact ms diff.
  • now_diff_milliseconds_undefined_test — the undefined-later-time branch.
  • now_diff_microseconds_test — synthetic integers, exact μs diff.
  • now_diff_microseconds_undefined_test — undefined branch on the microsecond path.

New coverage:

  • now_diff_wm_log_data_shape_test — constructs a real #wm_log_data{} with erlang:monotonic_time() values and diffs the fields via the new helpers. Requires the record definition (webmachine_logger.hrl) at test-compile time, which is what makes the contract binding: if the record's field type ever diverges from what the helpers accept, this test breaks at compile time (record construction) or runtime (function clause), whichever comes first. This is the check that would have caught the situation where the record moved to integers but now_diff_milliseconds/2 still only pattern-matched on tuples.
  • now_diff_milliseconds_realtime_testtimer:sleep(15) between two erlang:monotonic_time/0 calls, then asserts the diff is ≥ 15 ms and < 1000 ms. Catches unit-conversion regressions where a mis-typed target unit (e.g. nanosecond, second) would silently return a nonsensical number.

Verification

  • erlc -DTEST -I include src/webmachine_util.erl: clean compile.
  • All six new/updated now_diff_* tests pass.
  • Other pre-existing failures in the module's eunit suite (media_type_extra_whitespace_test, format_content_type_test, parse_range_test) are unrelated — they require mochiweb_util/mochiweb_http which weren't on the standalone erl -pa sandbox path.

samwar added 2 commits July 14, 2026 15:04
webmachine_decision_core:finish_response/2's new maybe_flush_req_body
step (added in 1.12) checks mochiweb_request_recv in the process
dictionary to decide whether the body still needs draining. That flag
is set by webmachine_request:call({req_body, ...}) inside
wrq:req_body/1, but applications that dispatch body reads to a
separate worker process end up with the flag on the worker's pdict
while the mochiweb loop process's pdict stays empty.

Consult ReqState#wm_reqstate.bodyfetch as a fallback. bodyfetch is
set to `standard` or `stream` in the same call that would set the
pdict flag, and unlike the pdict it travels with the ReqState value
across process boundaries. Applications that thread the updated
ReqState back to the mochiweb loop process (via the returned
Request's wm_state field) will hit the fallback and short-circuit
the drain.

Keep the existing pdict guard as the fast path for the common
single-process case, and keep FLUSH_TIMEOUT=5000 as the safety
net for edge cases where neither signal was set.

Also keep the 1.12.1-fe base fix: guard the `undefined` branch on
get(mochiweb_request_recv) =:= true and return `true` immediately
in that case (eager reads mark the request as recv'd; there's
nothing left on the socket to drain), and thread ?FLUSH_TIMEOUT
through a new recv_stream_body/3 variant that the drain fallback
uses so a misbehaving peer cannot wedge the pipeline. Legitimate
streaming callers keep ?IDLE_TIMEOUT = infinity via the 2-arg
wrapper.
The wm_log_data record migrated from os:timestamp() tuples to
erlang:monotonic_time() integers in native units, but
webmachine_util:now_diff_milliseconds/2 was left with the tuple
clauses only. Internal callers (webmachine_access_log_handler,
webmachine_perf_log_handler) had already switched to the new
webmachine_log:{request,post}_processing_time/1 helpers, so
now_diff_milliseconds/2 was effectively dead code inside webmachine
— but downstream consumers that read the record fields and diffed
them via now_diff_milliseconds/2 would hit
"no function clause matching now_diff_milliseconds(<neg-integer>,
<neg-integer>)" on the first log_access event.

Changes
-------
- Replace the tuple clauses of now_diff_milliseconds/2 with an
  integer-input path that delegates to erlang:convert_time_unit/3
  with a native → millisecond conversion.
- Add now_diff_microseconds/2 for consumers that emit response
  times at microsecond granularity (matches the older
  timer:now_diff/2 return unit).
- Extract diff_native/2 as a private helper so both public
  functions share the same undefined-argument handling. Semantics:
  undefined "later" time is treated as erlang:monotonic_time() —
  same convention webmachine_log:performance_time_diff/2 already
  uses.
- Update the eunit tests to construct start/end times as native-
  unit integers and to cover both millisecond and microsecond
  paths plus the undefined branch.
- Add now_diff_wm_log_data_shape_test/0 — a compile-and-runtime
  contract test that constructs a real #wm_log_data{} with
  monotonic-time values and diffs the fields via the new helpers.
  Catches record-shape / helper-input mismatches (which was the
  precise gap that let the tuple-clause code stay green after the
  record migrated to native integers).
- Add now_diff_milliseconds_realtime_test/0 — sleep 15ms, diff,
  assert the millisecond count matches wall clock. Catches
  unit-conversion regressions where a mis-typed `nanosecond` or
  `second` target would silently return a nonsensical number.
- Include webmachine_logger.hrl under -ifdef(TEST) so the record
  is available to the contract test without becoming a production
  compile-time dep.

Compatibility
-------------
Callers that used to pass {M,S,U} tuples will no longer match. In
practice no such callers survived the wm_log_data migration —
those tuple values were previously read out of the record and the
record has held integers for a while. Any external caller that
had somehow stayed on tuples would have been silently broken since
that migration; this PR turns the silent breakage into a compile-
time / runtime signal to update.
@samwar
samwar merged commit 3c0262f into main Jul 20, 2026
4 of 12 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant