Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

access log: added new COMMON_DURATION command #33240

Merged
merged 7 commits into from
Apr 3, 2024

Conversation

wbpcode
Copy link
Member

@wbpcode wbpcode commented Apr 1, 2024

Commit Message: access log: added new COMMON_DURATION command
Additional Description:

Added :ref:%COMMON_DURATION% to access log format to log the duration of the request. The start time point, end time point and duration precision can be configured in this new command.
For example, given following command
%COMMON_DURATION(DS_RX_BEG, US_TX_BEG, us)%,
Envoy will log the duration from the downstream request start to the upstream request start in the microseconds.

To close #33001

Risk Level: low.
Testing: unit.
Docs Changes: added.
Release Notes: added.
Platform Specific Features: n/a.

wbpcode added 2 commits April 1, 2024 11:46
Signed-off-by: wbpcode <wbphub@live.com>
Signed-off-by: wbpcode <wbphub@live.com>
@wbpcode
Copy link
Member Author

wbpcode commented Apr 1, 2024

I personally think the name of the time point is too long, may be we should use some short names here?

Here are current supported time point name:

    * ``FIRST_DOWNSTREAM_RX_BYTE_RECEIVED``: The time point of the first byte of downstream request is received. Same as ``START``.
    * ``LAST_DOWNSTREAM_RX_BYTE_RECEIVED``: The time point of the last byte of downstream request is received.
    * ``FIRST_UPSTREAM_TX_BYTE_SENT``: The time point of the first byte of upstream request is sent.
    * ``LAST_UPSTREAM_TX_BYTE_SENT``: The time point of the last byte of upstream request is sent.
    * ``FIRST_UPSTREAM_RX_BYTE_RECEIVED``: The time point of the first byte of upstream response is received.
    * ``LAST_UPSTREAM_RX_BYTE_RECEIVED``: The time point of the last byte of upstream response is received.
    * ``FIRST_DOWNSTREAM_TX_BYTE_SENT``: The time point of the first byte of downstream response is sent.
    * ``LAST_DOWNSTREAM_TX_BYTE_SENT``: The time point of the last byte of downstream response is sent.
    * Dynamic value: Any other values will be treated as custom time points that set by named keys in the downstream timing.

May be we can use some short abbreviations, for example:

DS_RX_BEG:FIRST_DOWNSTREAM_RX_BYTE_RECEIVED
US_TX_END:LAST_UPSTREAM_TX_BYTE_SENT

Then, the
%COMMON_DURATION(FIRST_DOWNSTREAM_RX_BYTE_RECEIVED, LAST_UPSTREAM_TX_BYTE_SENT)%
will become the
%COMMON_DURATION(DS_RX_BEG, US_TX_END)%
which is much shorter.

wbpcode added 3 commits April 1, 2024 14:12
Signed-off-by: wbpcode <wbphub@live.com>
Signed-off-by: wbpcode <wbphub@live.com>
Signed-off-by: wbpcode <wbphub@live.com>
@wbpcode
Copy link
Member Author

wbpcode commented Apr 1, 2024

This is new feature, so let's use the short name. it will make the log template simpler

    * ``DS_RX_BEG``: The time point of the downstream request receiving begin.
    * ``DS_RX_END``: The time point of the downstream request receiving end.
    * ``US_TX_BEG``: The time point of the upstream request sending begin.
    * ``US_TX_END``: The time point of the upstream request sending end.
    * ``US_RX_BEG``: The time point of the upstream response receiving begin.
    * ``US_RX_END``: The time point of the upstream response receiving end.
    * ``DS_TX_BEG``: The time point of the downstream response sending begin.
    * ``DS_TX_END``: The time point of the downstream response sending end.
    * Dynamic value: Other values will be treated as custom time points that set by named keys.

    The PRECISION is specified by the following values:

    * ``ms``: Millisecond precision.
    * ``us``: Microsecond precision.
    * ``ns``: Nanosecond precision.

@wbpcode
Copy link
Member Author

wbpcode commented Apr 2, 2024

/retest

Copy link
Contributor

@zirain zirain left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this will be really helpful when debuging, thanks!

Copy link
Member

@zuercher zuercher left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Generally, looks good. Some minor comments below.

docs/root/configuration/observability/access_log/usage.rst Outdated Show resolved Hide resolved
source/common/formatter/stream_info_formatter.cc Outdated Show resolved Hide resolved
Signed-off-by: wbpcode <wbphub@live.com>
@wbpcode
Copy link
Member Author

wbpcode commented Apr 2, 2024

/retest

@wbpcode wbpcode enabled auto-merge (squash) April 2, 2024 14:08
@wbpcode wbpcode merged commit 4886a6a into envoyproxy:main Apr 3, 2024
53 checks passed
@wbpcode wbpcode deleted the dev-duration branch April 4, 2024 03:05
alyssawilk pushed a commit to alyssawilk/envoy that referenced this pull request Apr 29, 2024
* access log: added new COMMON_DURATION command

Signed-off-by: wbpcode <wbphub@live.com>

* fix docs

Signed-off-by: wbpcode <wbphub@live.com>

* use short name

Signed-off-by: wbpcode <wbphub@live.com>

* fix format

Signed-off-by: wbpcode <wbphub@live.com>

* user lower case for precisons

Signed-off-by: wbpcode <wbphub@live.com>

* address comments

Signed-off-by: wbpcode <wbphub@live.com>

---------

Signed-off-by: wbpcode <wbphub@live.com>
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.

How to accurately measure processing latency?
3 participants