proxy timings#1717

i110 · 2018-03-30T04:45:21Z

Add a logging feature to log access timings to upstream servers

%{proxy-idle-time}x
%{proxy-connect-time}x
%{proxy-request-header-time}x
%{proxy-request-body-time}x
%{proxy-request-total-time}x
%{proxy-first-byte-time}x
%{proxy-response-time}x
%{proxy-total-time}x

TODO:

more granularity? (i.e. upstream-request-header-time, etc) It might needs some interface changes of http1client..
server-timings header
tests

kazuho

Thank you for working on this. I like the general approach proposed by the PR.

IIRC, the outcome of our discussion was that we will simply emit timing information of the upstream side (i.e. h2o acting as a client), rather than trying to build a generic framework to handle timing information. However, I see some part of the code trying to provide abstraction that seems to contradict with the decision.

Could you please clarify why they are necessary?

kazuho · 2018-04-04T04:55:48Z

include/h2o.h

+     */
+    struct {
+        h2o_proxy_log_data_t *proxy;
+    } handler_log_data;


Two questions here:

does proxy need to be a pointer?

do we need to wrap h2o_proxy_log_data_t with a struct named handler_log_data? I'd assume that the timing information we will be logging directly in h2o to be i) when the information is sent to the client and ii) when the information is generated by the generator. If my assumption is true, then we will have nothing other than proxy.

kazuho · 2018-04-04T04:56:33Z

include/h2o/http1client.h

+    uint64_t request_end_at;
+    uint64_t response_start_at;
+    uint64_t response_end_at;
+} h2o_http1client_timings_t;


kazuho · 2018-04-04T04:59:07Z

lib/core/logconf.c

+                        LAST_ELEMENT()->data.handler_cb = cb;
+                        goto MAP_EXT_Found;
+                    }
+


Can't we simply add ELEMENT_TYPE_PROXY_PROCESS_TIME etc. due to the same reason stated above?

i110 · 2018-04-04T05:13:38Z

Thank you for your comment. As you said I added a little abstraction because

I wanted to encapsulate actual logging logics in proxy.c. I anticipated that additional demands of logging like upstream-addr or upstream-status in nginx will be raised soonly. If that happen logconf.c will get too completed to maintain unless this encapsulating I think
other handler might want to add logging values in the future. %{mruby.foo}x or %{file.bar}x may be useful sometime

kazuho · 2018-04-04T05:34:47Z

Thank you for the answer.

The problem as I see is that the abstraction is incomplete. For example, existence of handler-specific type (i.e. h2o_req_t::handler_log_data.proxy) means that the feature is not handler-agnostic, while some of the functions (e.g. logger callbacks) are tried to be abstracted.

I also wonder it would be the right approach to let the handler define a dedicated callback for each log specifier would be the right approach for a genenic mechanism. For example, you might want to generate an arbitrary-named property in the mruby handler. But you cannot dynamically create a callback that binds to the named property.

In other words, I am backwards against trying to design a framework at the moment when there is no clear need for one.

i110 · 2018-04-04T05:56:13Z

the feature is not handler-agnostic, while some of the functions (e.g. logger callbacks) are tried to be abstracted.

I agree, it's sort of like result of compromise. I don't have objection to removing handler_log_data struct

For example, you might want to generate an arbitrary-named property in the mruby handler. But you cannot dynamically create a callback that binds to the named property.

In such a case, for example, mruby handler can catch mruby- prefix and run the callback written in mruby. Only thing I wanted to do is encapsulating the logics in each handlers, not developing framework.

i110 · 2018-04-04T07:19:47Z

@kazuho I addressed the issues and add tests.

kazuho · 2018-04-05T03:51:24Z

include/h2o.h

+    /**
+     * proxy log data
+     */
+    h2o_http1client_timings_t *proxy_timings;


Thank you for the changes.

How about adding h2o_http1client_timings_t (not a pointer) as a member of h2o_req_t::timestamps?

By doing so, I believe that we can drastically reduce the changes. For example, there would be no need for new functions like h2o_proxy_time_compute_.... All we need to do in core is to support new variables in logconf.c.

i110 · 2018-04-13T09:34:25Z

@kazuho Thank you for your comment. I addressed the issues.

kazuho

Thank you for the changes. Aside from the comment below I think that the code is ready for merge.

kazuho · 2018-04-19T01:14:59Z

lib/core/util.c

+        DELIMITER ELEMENT_LONGEST_STR("process") DELIMITER ELEMENT_LONGEST_STR("proxy-idle")                                       \
+            DELIMITER ELEMENT_LONGEST_STR("proxy-connect") DELIMITER ELEMENT_LONGEST_STR("proxy-request-header")                   \
+                DELIMITER ELEMENT_LONGEST_STR("proxy-request-body") DELIMITER ELEMENT_LONGEST_STR("proxy-request-total")           \
+                    DELIMITER ELEMENT_LONGEST_STR("proxy-first-byte")


Do these field names match those that are actually being emitted?

oops, thank you for finding this. Fixed at 06b4a9b
And also I found similar bug exists in h2o_build_server_timing_trailer, then I fixed it at ce33863

kazuho · 2018-04-20T04:20:43Z

lib/core/util.c

-                           prefix_len + suffix_len + sizeof(ELEMENT_LONGEST_STR(response) DELIMITER ELEMENT_LONGEST_STR(total)));
+    value.base = h2o_mem_alloc_pool(&req->pool, *value.base,
+                                    prefix_len + suffix_len +
+                                        sizeof(ELEMENT_LONGEST_STR("response") DELIMITER ELEMENT_LONGEST_STR("total")));


Do we have enough space here now that we might also be sending timings for proxy-response and proxy-total?

kazuho · 2018-05-29T06:13:33Z

Thank you for the changes. Merged to master.

i110 added 2 commits March 30, 2018 18:37

add upstream timing logs

f070522

add proxy timing values to server-timing header

cc3ae87

i110 force-pushed the i110/upstream-timings branch from 5703a0f to cc3ae87 Compare March 30, 2018 10:10

i110 changed the title ~~[WIP] upstream timing logs~~ proxy timing logs Mar 30, 2018

i110 changed the title ~~proxy timing logs~~ proxy timings Mar 30, 2018

kazuho reviewed Apr 4, 2018

View reviewed changes

i110 added 4 commits April 4, 2018 16:06

remove proxy timing abstraction

9beb666

remove h2o_proxy_log_data_t

f668b15

reformat

70c1d34

add proxy timing tests

ef44684

kazuho reviewed Apr 5, 2018

View reviewed changes

i110 added 6 commits April 13, 2018 15:11

Merge branch 'master' into i110/upstream-timings

d6817a6

merge request-header-time and request-body-time to request-time

58968a9

minimize code changes

a01492d

rename proxy-first-byte-time to proxy-process-time

bcf3e80

add server-timing test for proxy-timings

624177b

remove proxy-connect-time test for it's difficulty

e47caba

kazuho reviewed Apr 19, 2018

View reviewed changes

fix mismatched names

06b4a9b

kazuho reviewed Apr 20, 2018

View reviewed changes

fix length calculation bug of trailer header

ce33863

kazuho merged commit 5597dbe into master May 29, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

proxy timings#1717

proxy timings #1717

i110 commented Mar 30, 2018 •
edited

Loading

kazuho left a comment

kazuho Apr 4, 2018

kazuho Apr 4, 2018

kazuho Apr 4, 2018

i110 commented Apr 4, 2018

kazuho commented Apr 4, 2018

i110 commented Apr 4, 2018

i110 commented Apr 4, 2018

kazuho Apr 5, 2018

i110 commented Apr 13, 2018

kazuho left a comment

kazuho Apr 19, 2018

i110 Apr 20, 2018

kazuho Apr 20, 2018

kazuho commented May 29, 2018

proxy timings#1717

proxy timings #1717

Conversation

i110 commented Mar 30, 2018 • edited Loading

kazuho left a comment

Choose a reason for hiding this comment

kazuho Apr 4, 2018

Choose a reason for hiding this comment

kazuho Apr 4, 2018

Choose a reason for hiding this comment

kazuho Apr 4, 2018

Choose a reason for hiding this comment

i110 commented Apr 4, 2018

kazuho commented Apr 4, 2018

i110 commented Apr 4, 2018

i110 commented Apr 4, 2018

kazuho Apr 5, 2018

Choose a reason for hiding this comment

i110 commented Apr 13, 2018

kazuho left a comment

Choose a reason for hiding this comment

kazuho Apr 19, 2018

Choose a reason for hiding this comment

i110 Apr 20, 2018

Choose a reason for hiding this comment

kazuho Apr 20, 2018

Choose a reason for hiding this comment

kazuho commented May 29, 2018

i110 commented Mar 30, 2018 •
edited

Loading