Merge pull request grpc#8662 from markdroth/latency_in_final_info

Populate latency field in final_info.

Makefile

@@ -6994,6 +6994,7 @@ LIBEND2END_TESTS_SRC = \
     test/core/end2end/tests/empty_batch.c \
     test/core/end2end/tests/filter_call_init_fails.c \
     test/core/end2end/tests/filter_causes_close.c \
+    test/core/end2end/tests/filter_latency.c \
     test/core/end2end/tests/graceful_server_shutdown.c \
     test/core/end2end/tests/high_initial_seqno.c \
     test/core/end2end/tests/hpack_size.c \
@@ -7079,6 +7080,7 @@ LIBEND2END_NOSEC_TESTS_SRC = \
     test/core/end2end/tests/empty_batch.c \
     test/core/end2end/tests/filter_call_init_fails.c \
     test/core/end2end/tests/filter_causes_close.c \
+    test/core/end2end/tests/filter_latency.c \
     test/core/end2end/tests/graceful_server_shutdown.c \
     test/core/end2end/tests/high_initial_seqno.c \
     test/core/end2end/tests/hpack_size.c \

src/core/ext/client_channel/client_channel.c

@@ -641,7 +641,7 @@ static void subchannel_ready(grpc_exec_ctx *exec_ctx, void *arg,
     grpc_subchannel_call *subchannel_call = NULL;
     grpc_error *new_error = grpc_connected_subchannel_create_call(
         exec_ctx, calld->connected_subchannel, calld->pollent, calld->path,
-        calld->deadline, &subchannel_call);
+        calld->call_start_time, calld->deadline, &subchannel_call);
     if (new_error != GRPC_ERROR_NONE) {
       new_error = grpc_error_add_child(new_error, error);
       subchannel_call = CANCELLED_CALL;
@@ -894,7 +894,7 @@ static void cc_start_transport_stream_op(grpc_exec_ctx *exec_ctx,
     grpc_subchannel_call *subchannel_call = NULL;
     grpc_error *error = grpc_connected_subchannel_create_call(
         exec_ctx, calld->connected_subchannel, calld->pollent, calld->path,
-        calld->deadline, &subchannel_call);
+        calld->call_start_time, calld->deadline, &subchannel_call);
     if (error != GRPC_ERROR_NONE) {
       subchannel_call = CANCELLED_CALL;
       fail_locked(exec_ctx, calld, GRPC_ERROR_REF(error));

src/core/ext/client_channel/subchannel.c

@@ -702,15 +702,15 @@ grpc_connected_subchannel *grpc_subchannel_get_connected_subchannel(
 
 grpc_error *grpc_connected_subchannel_create_call(
     grpc_exec_ctx *exec_ctx, grpc_connected_subchannel *con,
-    grpc_polling_entity *pollent, grpc_mdstr *path, gpr_timespec deadline,
-    grpc_subchannel_call **call) {
+    grpc_polling_entity *pollent, grpc_mdstr *path, gpr_timespec start_time,
+    gpr_timespec deadline, grpc_subchannel_call **call) {
   grpc_channel_stack *chanstk = CHANNEL_STACK_FROM_CONNECTION(con);
   *call = gpr_malloc(sizeof(grpc_subchannel_call) + chanstk->call_stack_size);
   grpc_call_stack *callstk = SUBCHANNEL_CALL_TO_CALL_STACK(*call);
   (*call)->connection = con;  // Ref is added below.
   grpc_error *error =
       grpc_call_stack_init(exec_ctx, chanstk, 1, subchannel_call_destroy, *call,
-                           NULL, NULL, path, deadline, callstk);
+                           NULL, NULL, path, start_time, deadline, callstk);
   if (error != GRPC_ERROR_NONE) {
     const char *error_string = grpc_error_string(error);
     gpr_log(GPR_ERROR, "error: %s", error_string);

src/core/ext/client_channel/subchannel.h

@@ -111,8 +111,8 @@ void grpc_subchannel_call_unref(grpc_exec_ctx *exec_ctx,
 /** construct a subchannel call */
 grpc_error *grpc_connected_subchannel_create_call(
     grpc_exec_ctx *exec_ctx, grpc_connected_subchannel *connected_subchannel,
-    grpc_polling_entity *pollent, grpc_mdstr *path, gpr_timespec deadline,
-    grpc_subchannel_call **subchannel_call);
+    grpc_polling_entity *pollent, grpc_mdstr *path, gpr_timespec start_time,
+    gpr_timespec deadline, grpc_subchannel_call **subchannel_call);
 
 /** process a transport level op */
 void grpc_connected_subchannel_process_transport_op(

src/core/lib/channel/channel_stack.c

@@ -162,7 +162,8 @@ grpc_error *grpc_call_stack_init(
     grpc_exec_ctx *exec_ctx, grpc_channel_stack *channel_stack,
     int initial_refs, grpc_iomgr_cb_func destroy, void *destroy_arg,
     grpc_call_context_element *context, const void *transport_server_data,
-    grpc_mdstr *path, gpr_timespec deadline, grpc_call_stack *call_stack) {
+    grpc_mdstr *path, gpr_timespec start_time, gpr_timespec deadline,
+    grpc_call_stack *call_stack) {
   grpc_channel_element *channel_elems = CHANNEL_ELEMS_FROM_STACK(channel_stack);
   grpc_call_element_args args;
   size_t count = channel_stack->count;
@@ -179,7 +180,7 @@ grpc_error *grpc_call_stack_init(
 
   /* init per-filter data */
   grpc_error *first_error = GRPC_ERROR_NONE;
-  args.start_time = gpr_now(GPR_CLOCK_MONOTONIC);
+  args.start_time = start_time;
   for (i = 0; i < count; i++) {
     args.call_stack = call_stack;
     args.server_transport_data = transport_server_data;

src/core/lib/channel/channel_stack.h

@@ -231,7 +231,8 @@ grpc_error *grpc_call_stack_init(
     grpc_exec_ctx *exec_ctx, grpc_channel_stack *channel_stack,
     int initial_refs, grpc_iomgr_cb_func destroy, void *destroy_arg,
     grpc_call_context_element *context, const void *transport_server_data,
-    grpc_mdstr *path, gpr_timespec deadline, grpc_call_stack *call_stack);
+    grpc_mdstr *path, gpr_timespec start_time, gpr_timespec deadline,
+    grpc_call_stack *call_stack);
 /* Set a pollset or a pollset_set for a call stack: must occur before the first
  * op is started */
 void grpc_call_stack_set_pollset_or_pollset_set(grpc_exec_ctx *exec_ctx,

src/core/lib/surface/call.c

@@ -123,6 +123,7 @@ struct grpc_call {
   grpc_channel *channel;
   grpc_call *parent;
   grpc_call *first_child;
+  gpr_timespec start_time;
   /* TODO(ctiller): share with cq if possible? */
   gpr_mu mu;
 
@@ -240,6 +241,7 @@ grpc_error *grpc_call_create(const grpc_call_create_args *args,
   call->channel = args->channel;
   call->cq = args->cq;
   call->parent = args->parent_call;
+  call->start_time = gpr_now(GPR_CLOCK_MONOTONIC);
   /* Always support no compression */
   GPR_BITSET(&call->encodings_accepted_by_peer, GRPC_COMPRESS_NONE);
   call->is_client = args->server_transport_data == NULL;
@@ -312,10 +314,10 @@ grpc_error *grpc_call_create(const grpc_call_create_args *args,
 
   GRPC_CHANNEL_INTERNAL_REF(args->channel, "call");
   /* initial refcount dropped by grpc_call_destroy */
-  grpc_error *error =
-      grpc_call_stack_init(&exec_ctx, channel_stack, 1, destroy_call, call,
-                           call->context, args->server_transport_data, path,
-                           send_deadline, CALL_STACK_FROM_CALL(call));
+  grpc_error *error = grpc_call_stack_init(
+      &exec_ctx, channel_stack, 1, destroy_call, call, call->context,
+      args->server_transport_data, path, call->start_time, send_deadline,
+      CALL_STACK_FROM_CALL(call));
   if (error != GRPC_ERROR_NONE) {
     grpc_status_code status;
     const char *error_str;
@@ -428,6 +430,8 @@ static void destroy_call(grpc_exec_ctx *exec_ctx, void *call,
 
   get_final_status(call, set_status_value_directly,
                    &c->final_info.final_status);
+  c->final_info.stats.latency =
+      gpr_time_sub(gpr_now(GPR_CLOCK_MONOTONIC), c->start_time);
 
   grpc_call_stack_destroy(exec_ctx, CALL_STACK_FROM_CALL(c), &c->final_info, c);
   GRPC_CHANNEL_INTERNAL_UNREF(exec_ctx, channel, "call");

test/core/channel/channel_stack_test.c

@@ -137,9 +137,10 @@ static void test_create_channel_stack(void) {
   GPR_ASSERT(*channel_data == 0);
 
   call_stack = gpr_malloc(channel_stack->call_stack_size);
-  grpc_error *error = grpc_call_stack_init(
-      &exec_ctx, channel_stack, 1, free_call, call_stack, NULL, NULL, path,
-      gpr_inf_future(GPR_CLOCK_MONOTONIC), call_stack);
+  grpc_error *error =
+      grpc_call_stack_init(&exec_ctx, channel_stack, 1, free_call, call_stack,
+                           NULL, NULL, path, gpr_now(GPR_CLOCK_MONOTONIC),
+                           gpr_inf_future(GPR_CLOCK_MONOTONIC), call_stack);
   GPR_ASSERT(error == GRPC_ERROR_NONE);
   GPR_ASSERT(call_stack->count == 1);
   call_elem = grpc_call_stack_element(call_stack, 0);

test/core/end2end/end2end_nosec_tests.c

@@ -75,6 +75,8 @@ extern void filter_call_init_fails(grpc_end2end_test_config config);
 extern void filter_call_init_fails_pre_init(void);
 extern void filter_causes_close(grpc_end2end_test_config config);
 extern void filter_causes_close_pre_init(void);
+extern void filter_latency(grpc_end2end_test_config config);
+extern void filter_latency_pre_init(void);
 extern void graceful_server_shutdown(grpc_end2end_test_config config);
 extern void graceful_server_shutdown_pre_init(void);
 extern void high_initial_seqno(grpc_end2end_test_config config);
@@ -153,6 +155,7 @@ void grpc_end2end_tests_pre_init(void) {
   empty_batch_pre_init();
   filter_call_init_fails_pre_init();
   filter_causes_close_pre_init();
+  filter_latency_pre_init();
   graceful_server_shutdown_pre_init();
   high_initial_seqno_pre_init();
   hpack_size_pre_init();
@@ -207,6 +210,7 @@ void grpc_end2end_tests(int argc, char **argv,
     empty_batch(config);
     filter_call_init_fails(config);
     filter_causes_close(config);
+    filter_latency(config);
     graceful_server_shutdown(config);
     high_initial_seqno(config);
     hpack_size(config);
@@ -304,6 +308,10 @@ void grpc_end2end_tests(int argc, char **argv,
       filter_causes_close(config);
       continue;
     }
+    if (0 == strcmp("filter_latency", argv[i])) {
+      filter_latency(config);
+      continue;
+    }
     if (0 == strcmp("graceful_server_shutdown", argv[i])) {
       graceful_server_shutdown(config);
       continue;

test/core/end2end/end2end_tests.c

@@ -77,6 +77,8 @@ extern void filter_call_init_fails(grpc_end2end_test_config config);
 extern void filter_call_init_fails_pre_init(void);
 extern void filter_causes_close(grpc_end2end_test_config config);
 extern void filter_causes_close_pre_init(void);
+extern void filter_latency(grpc_end2end_test_config config);
+extern void filter_latency_pre_init(void);
 extern void graceful_server_shutdown(grpc_end2end_test_config config);
 extern void graceful_server_shutdown_pre_init(void);
 extern void high_initial_seqno(grpc_end2end_test_config config);
@@ -156,6 +158,7 @@ void grpc_end2end_tests_pre_init(void) {
   empty_batch_pre_init();
   filter_call_init_fails_pre_init();
   filter_causes_close_pre_init();
+  filter_latency_pre_init();
   graceful_server_shutdown_pre_init();
   high_initial_seqno_pre_init();
   hpack_size_pre_init();
@@ -211,6 +214,7 @@ void grpc_end2end_tests(int argc, char **argv,
     empty_batch(config);
     filter_call_init_fails(config);
     filter_causes_close(config);
+    filter_latency(config);
     graceful_server_shutdown(config);
     high_initial_seqno(config);
     hpack_size(config);
@@ -312,6 +316,10 @@ void grpc_end2end_tests(int argc, char **argv,
       filter_causes_close(config);
       continue;
     }
+    if (0 == strcmp("filter_latency", argv[i])) {
+      filter_latency(config);
+      continue;
+    }
     if (0 == strcmp("graceful_server_shutdown", argv[i])) {
       graceful_server_shutdown(config);
       continue;

test/core/end2end/gen_build_yaml.py

@@ -111,6 +111,7 @@
     'empty_batch': default_test_options,
     'filter_causes_close': default_test_options,
     'filter_call_init_fails': default_test_options,
+    'filter_latency': default_test_options,
     'graceful_server_shutdown': default_test_options._replace(cpu_cost=LOWCPU),
     'hpack_size': default_test_options._replace(proxyable=False,
                                                 traceable=False),