webmachine_util: monotonic-time-aware now_diff helpers - #1
Merged
Conversation
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.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Finishes migrating
webmachine_util:now_diff_milliseconds/2offos:timestamp()tuples and onto theerlang:monotonic_time()native-integer inputs thewm_log_datarecord has been carrying for a while. Adds a matchingnow_diff_microseconds/2so downstream access-log handlers don't need to duplicate the conversion.Motivation
The
wm_log_datarecord'sstart_time,end_time, andfinish_timefields were migrated fromos:timestamp()tuples toerlang:monotonic_time()integers in native units. Internal callers (webmachine_access_log_handler,webmachine_perf_log_handler) followed suit and moved to the newwebmachine_log:{request,post}_processing_time/1helpers.What got left behind was
webmachine_util:now_diff_milliseconds/2— still exported public API, still tuple-only:Any downstream consumer with its own gen_event handler that reads
start_time/end_timeoffwm_log_dataand diffs them via this function will hitno 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 toerlang:convert_time_unit(Diff, native, millisecond). Undefined "later" time is treated aserlang:monotonic_time()— same conventionwebmachine_log:performance_time_diff/2uses.now_diff_microseconds/2— new, matching shape. Matches the oldertimer:now_diff/2return 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.Compatibility
Tuple callers will no longer match. In practice, no such callers should exist:
start_time/end_timeoff the record has been passing integers tonow_diff_milliseconds/2since that migration and getting silent runtime crashes.webmachine_log:{request,post}_processing_time/1in 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{}witherlang: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 butnow_diff_milliseconds/2still only pattern-matched on tuples.now_diff_milliseconds_realtime_test—timer:sleep(15)between twoerlang:monotonic_time/0calls, 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.now_diff_*tests pass.media_type_extra_whitespace_test,format_content_type_test,parse_range_test) are unrelated — they requiremochiweb_util/mochiweb_httpwhich weren't on the standaloneerl -pasandbox path.