Skip to content

Commit 2b39a5d

Browse files
grcevskigrcevski
authored
Implement correct request time tracking for non-Go programs (#629)
1 parent 4cb0ee0 commit 2b39a5d

File tree

8 files changed

+159
-60
lines changed

8 files changed

+159
-60
lines changed

‎bpf/common/http_info.h‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@ typedef struct http_info {
2121
connection_info_t conn_info;
2222
u64 start_monotime_ns;
2323
u64 end_monotime_ns;
24+
u64 req_monotime_ns;
2425
u64 extra_id;
2526
tp_info_t tp;
2627
pid_info pid;

‎bpf/generictracer/k_tracer.c‎

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@
2929

3030
#include <logger/bpf_dbg.h>
3131

32+
#include <maps/accepted_connections.h>
3233
#include <maps/fd_map.h>
3334
#include <maps/fd_to_connection.h>
3435
#include <maps/msg_buffers.h>
@@ -150,7 +151,7 @@ int BPF_KRETPROBE(obi_kretprobe_sys_accept4, s32 fd) {
150151
store_accept_fd_info(host_pid, fd, &info.p_conn.conn);
151152

152153
u16 orig_dport = info.p_conn.conn.d_port;
153-
//dbg_print_http_connection_info(&info.p_conn.conn);
154+
dbg_print_http_connection_info(&info.p_conn.conn);
154155
sort_connection_info(&info.p_conn.conn);
155156
info.p_conn.pid = pid_from_pid_tgid(id);
156157
info.orig_dport = orig_dport;
@@ -164,6 +165,10 @@ int BPF_KRETPROBE(obi_kretprobe_sys_accept4, s32 fd) {
164165
// find_nodejs_parent_trace() for usage
165166
// TODO: try to merge with store_accept_fd_info() above
166167
bpf_map_update_elem(&fd_to_connection, &key, &info.p_conn.conn, BPF_ANY);
168+
169+
u64 accept_time = bpf_ktime_get_ns();
170+
171+
bpf_map_update_elem(&accepted_connections, &info.p_conn.conn, &accept_time, BPF_ANY);
167172
} else {
168173
bpf_dbg_printk("Failed to parse accept socket info");
169174
}
@@ -554,6 +559,7 @@ int BPF_KPROBE(obi_kprobe_tcp_close, struct sock *sk, long timeout) {
554559
bpf_map_delete_elem(&ongoing_tcp_req, &info);
555560
delete_backup_sk_buff(&info.conn);
556561
cleanup_tcp_trace_info_if_needed(&info);
562+
bpf_map_delete_elem(&accepted_connections, &info.conn);
557563
}
558564

559565
bpf_map_delete_elem(&active_send_args, &id);

‎bpf/generictracer/protocol_http.h‎

Lines changed: 16 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@
1515
#include <generictracer/maps/http_info_mem.h>
1616
#include <generictracer/protocol_common.h>
1717

18+
#include <maps/accepted_connections.h>
1819
#include <maps/active_ssl_connections.h>
1920
#include <maps/ongoing_http.h>
2021

@@ -344,7 +345,21 @@ static __always_inline void process_http_request(
344345

345346
fixup_connection_info(&info->conn_info, info->type == EVENT_HTTP_CLIENT, orig_dport);
346347

347-
info->start_monotime_ns = bpf_ktime_get_ns();
348+
u64 start_time = bpf_ktime_get_ns();
349+
u64 req_time = start_time;
350+
351+
if (info->type == EVENT_HTTP_REQUEST) {
352+
u64 *accept_time = bpf_map_lookup_elem(&accepted_connections, &info->conn_info);
353+
if (accept_time) {
354+
bpf_d_printk("prev_start_time %ld actual_start_time %ld", start_time, *accept_time);
355+
req_time = *accept_time;
356+
// delete just in case the connection is reused, so we don't produce wrong info
357+
bpf_map_delete_elem(&accepted_connections, &info->conn_info);
358+
}
359+
}
360+
361+
info->start_monotime_ns = start_time;
362+
info->req_monotime_ns = req_time;
348363
info->status = 0;
349364
info->len = len;
350365
info->extra_id = extra_runtime_id(); // required for deleting the trace information

‎bpf/maps/accepted_connections.h‎

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,20 @@
1+
// Copyright The OpenTelemetry Authors
2+
// SPDX-License-Identifier: Apache-2.0
3+
4+
#pragma once
5+
6+
#include <bpfcore/vmlinux.h>
7+
#include <bpfcore/bpf_helpers.h>
8+
9+
#include <common/connection_info.h>
10+
#include <common/fd_key.h>
11+
#include <common/map_sizing.h>
12+
#include <common/pin_internal.h>
13+
14+
struct {
15+
__uint(type, BPF_MAP_TYPE_LRU_HASH);
16+
__type(key, connection_info_t); // connection info
17+
__type(value, u64); // time
18+
__uint(max_entries, MAX_CONCURRENT_SHARED_REQUESTS);
19+
__uint(pinning, OBI_PIN_INTERNAL);
20+
} accepted_connections SEC(".maps");

‎pkg/components/ebpf/common/httpfltr_test.go‎

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -95,6 +95,7 @@ func TestToRequestTrace(t *testing.T) {
9595

9696
var record BPFHTTPInfo
9797
record.Type = 1
98+
record.ReqMonotimeNs = 123450
9899
record.StartMonotimeNs = 123456
99100
record.EndMonotimeNs = 789012
100101
record.Status = 200
@@ -117,7 +118,7 @@ func TestToRequestTrace(t *testing.T) {
117118
Method: "GET",
118119
Status: 200,
119120
Type: request.EventTypeHTTP,
120-
RequestStart: 123456,
121+
RequestStart: 123450,
121122
Start: 123456,
122123
End: 789012,
123124
HostPort: 1,
@@ -132,6 +133,7 @@ func TestToRequestTraceNoConnection(t *testing.T) {
132133

133134
var record BPFHTTPInfo
134135
record.Type = 1
136+
record.ReqMonotimeNs = 123450
135137
record.StartMonotimeNs = 123456
136138
record.EndMonotimeNs = 789012
137139
record.Status = 200
@@ -154,7 +156,7 @@ func TestToRequestTraceNoConnection(t *testing.T) {
154156
Method: "GET",
155157
Type: request.EventTypeHTTP,
156158
Start: 123456,
157-
RequestStart: 123456,
159+
RequestStart: 123450,
158160
End: 789012,
159161
Status: 200,
160162
HostPort: 7033,
@@ -169,6 +171,7 @@ func TestToRequestTrace_BadHost(t *testing.T) {
169171

170172
var record BPFHTTPInfo
171173
record.Type = 1
174+
record.ReqMonotimeNs = 123450
172175
record.StartMonotimeNs = 123456
173176
record.EndMonotimeNs = 789012
174177
record.Status = 200
@@ -192,7 +195,7 @@ func TestToRequestTrace_BadHost(t *testing.T) {
192195
Method: "GET",
193196
Status: 200,
194197
Type: request.EventTypeHTTP,
195-
RequestStart: 123456,
198+
RequestStart: 123450,
196199
Start: 123456,
197200
End: 789012,
198201
HostPort: 0,

‎pkg/components/ebpf/common/httpfltr_transform.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -30,7 +30,7 @@ func httpInfoToSpan(info *HTTPInfo) request.Span {
3030
HostPort: int(info.ConnInfo.D_port),
3131
ContentLength: int64(info.Len),
3232
ResponseLength: int64(info.RespLen),
33-
RequestStart: int64(info.StartMonotimeNs),
33+
RequestStart: int64(info.ReqMonotimeNs),
3434
Start: int64(info.StartMonotimeNs),
3535
End: int64(info.EndMonotimeNs),
3636
Status: int(info.Status),

‎pkg/components/ebpf/common/httpfltr_transform_test.go‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -64,6 +64,7 @@ func makeHTTPInfo(method, path, peer, host string, peerPort, hostPort uint32, st
6464
bpfInfo := BPFHTTPInfo{
6565
Type: 1,
6666
Status: status,
67+
ReqMonotimeNs: durationMs * 1000000,
6768
StartMonotimeNs: durationMs * 1000000,
6869
EndMonotimeNs: durationMs * 2 * 1000000,
6970
}

‎test/integration/traces_test.go‎

Lines changed: 107 additions & 54 deletions
Original file line numberDiff line numberDiff line change
@@ -1014,68 +1014,96 @@ func testHTTPTracesNestedSelfCalls(t *testing.T) {
10141014
traces := tq.FindBySpan(jaeger.Tag{Key: "url.path", Type: "string", Value: "/api1"})
10151015
require.Len(t, traces, 1)
10161016
trace = traces[0]
1017-
}, test.Interval(100*time.Millisecond))
10181017

1019-
// Check the information of the parent span
1020-
res := trace.FindByOperationName("GET /api1", "")
1021-
require.Len(t, res, 1)
1022-
server := res[0]
1023-
require.NotEmpty(t, server.TraceID)
1024-
require.NotEmpty(t, server.SpanID)
1025-
parentID = server.SpanID
1018+
// Check the information of the parent span
1019+
res := trace.FindByOperationName("GET /api1", "")
1020+
require.Len(t, res, 1)
1021+
server := res[0]
1022+
require.NotEmpty(t, server.TraceID)
1023+
require.NotEmpty(t, server.SpanID)
1024+
parentID = server.SpanID
10261025

1027-
// check span attributes
1028-
sd := server.Diff(
1029-
jaeger.Tag{Key: "http.request.method", Type: "string", Value: "GET"},
1030-
jaeger.Tag{Key: "http.response.status_code", Type: "int64", Value: float64(200)},
1031-
jaeger.Tag{Key: "url.path", Type: "string", Value: "/api1"},
1032-
jaeger.Tag{Key: "server.port", Type: "int64", Value: float64(7771)},
1033-
jaeger.Tag{Key: "http.route", Type: "string", Value: "/api1"},
1034-
jaeger.Tag{Key: "span.kind", Type: "string", Value: "server"},
1035-
)
1036-
assert.Empty(t, sd, sd.String())
1026+
// check span attributes
1027+
sd := server.Diff(
1028+
jaeger.Tag{Key: "http.request.method", Type: "string", Value: "GET"},
1029+
jaeger.Tag{Key: "http.response.status_code", Type: "int64", Value: float64(200)},
1030+
jaeger.Tag{Key: "url.path", Type: "string", Value: "/api1"},
1031+
jaeger.Tag{Key: "server.port", Type: "int64", Value: float64(7771)},
1032+
jaeger.Tag{Key: "http.route", Type: "string", Value: "/api1"},
1033+
jaeger.Tag{Key: "span.kind", Type: "string", Value: "server"},
1034+
)
1035+
assert.Empty(t, sd, sd.String())
10371036

1038-
children := trace.ChildrenOf(parentID)
1039-
require.Len(t, children, 1)
1040-
child := children[0]
1037+
children := trace.ChildrenOf(parentID)
1038+
require.GreaterOrEqual(t, len(children), 1)
10411039

1042-
sd = child.Diff(
1043-
jaeger.Tag{Key: "http.request.method", Type: "string", Value: "GET"},
1044-
jaeger.Tag{Key: "http.response.status_code", Type: "int64", Value: float64(200)},
1045-
jaeger.Tag{Key: "url.path", Type: "string", Value: "/api2"},
1046-
jaeger.Tag{Key: "server.port", Type: "int64", Value: float64(7772)},
1047-
jaeger.Tag{Key: "http.route", Type: "string", Value: "/api2"},
1048-
jaeger.Tag{Key: "span.kind", Type: "string", Value: "server"},
1049-
)
1050-
assert.Empty(t, sd, sd.String())
1040+
// We've created the in-queue and processing spans
1041+
for _, c := range children {
1042+
children = trace.ChildrenOf(c.SpanID)
1043+
if len(children) > 0 {
1044+
break
1045+
}
1046+
}
10511047

1052-
children = trace.ChildrenOf(child.SpanID)
1053-
require.Len(t, children, 1)
1054-
child = children[0]
1048+
require.Len(t, children, 1)
1049+
child := children[0]
10551050

1056-
sd = child.Diff(
1057-
jaeger.Tag{Key: "http.request.method", Type: "string", Value: "GET"},
1058-
jaeger.Tag{Key: "http.response.status_code", Type: "int64", Value: float64(200)},
1059-
jaeger.Tag{Key: "url.path", Type: "string", Value: "/api3"},
1060-
jaeger.Tag{Key: "server.port", Type: "int64", Value: float64(7773)},
1061-
jaeger.Tag{Key: "http.route", Type: "string", Value: "/api3"},
1062-
jaeger.Tag{Key: "span.kind", Type: "string", Value: "server"},
1063-
)
1064-
assert.Empty(t, sd, sd.String())
1051+
sd = child.Diff(
1052+
jaeger.Tag{Key: "http.request.method", Type: "string", Value: "GET"},
1053+
jaeger.Tag{Key: "http.response.status_code", Type: "int64", Value: float64(200)},
1054+
jaeger.Tag{Key: "url.path", Type: "string", Value: "/api2"},
1055+
jaeger.Tag{Key: "server.port", Type: "int64", Value: float64(7772)},
1056+
jaeger.Tag{Key: "http.route", Type: "string", Value: "/api2"},
1057+
jaeger.Tag{Key: "span.kind", Type: "string", Value: "server"},
1058+
)
1059+
assert.Empty(t, sd, sd.String())
10651060

1066-
children = trace.ChildrenOf(child.SpanID)
1067-
require.Len(t, children, 1)
1068-
child = children[0]
1061+
children = trace.ChildrenOf(child.SpanID)
1062+
require.GreaterOrEqual(t, len(children), 1)
10691063

1070-
sd = child.Diff(
1071-
jaeger.Tag{Key: "http.request.method", Type: "string", Value: "GET"},
1072-
jaeger.Tag{Key: "http.response.status_code", Type: "int64", Value: float64(200)},
1073-
jaeger.Tag{Key: "url.path", Type: "string", Value: "/api4"},
1074-
jaeger.Tag{Key: "server.port", Type: "int64", Value: float64(7774)},
1075-
jaeger.Tag{Key: "http.route", Type: "string", Value: "/api4"},
1076-
jaeger.Tag{Key: "span.kind", Type: "string", Value: "server"},
1077-
)
1078-
assert.Empty(t, sd, sd.String())
1064+
for _, c := range children {
1065+
children = trace.ChildrenOf(c.SpanID)
1066+
if len(children) > 0 {
1067+
break
1068+
}
1069+
}
1070+
1071+
require.Len(t, children, 1)
1072+
child = children[0]
1073+
1074+
sd = child.Diff(
1075+
jaeger.Tag{Key: "http.request.method", Type: "string", Value: "GET"},
1076+
jaeger.Tag{Key: "http.response.status_code", Type: "int64", Value: float64(200)},
1077+
jaeger.Tag{Key: "url.path", Type: "string", Value: "/api3"},
1078+
jaeger.Tag{Key: "server.port", Type: "int64", Value: float64(7773)},
1079+
jaeger.Tag{Key: "http.route", Type: "string", Value: "/api3"},
1080+
jaeger.Tag{Key: "span.kind", Type: "string", Value: "server"},
1081+
)
1082+
assert.Empty(t, sd, sd.String())
1083+
1084+
children = trace.ChildrenOf(child.SpanID)
1085+
require.GreaterOrEqual(t, len(children), 1)
1086+
1087+
for _, c := range children {
1088+
children = trace.ChildrenOf(c.SpanID)
1089+
if len(children) > 0 {
1090+
break
1091+
}
1092+
}
1093+
1094+
require.Len(t, children, 1)
1095+
child = children[0]
1096+
1097+
sd = child.Diff(
1098+
jaeger.Tag{Key: "http.request.method", Type: "string", Value: "GET"},
1099+
jaeger.Tag{Key: "http.response.status_code", Type: "int64", Value: float64(200)},
1100+
jaeger.Tag{Key: "url.path", Type: "string", Value: "/api4"},
1101+
jaeger.Tag{Key: "server.port", Type: "int64", Value: float64(7774)},
1102+
jaeger.Tag{Key: "http.route", Type: "string", Value: "/api4"},
1103+
jaeger.Tag{Key: "span.kind", Type: "string", Value: "server"},
1104+
)
1105+
assert.Empty(t, sd, sd.String())
1106+
}, test.Interval(100*time.Millisecond))
10791107
}
10801108

10811109
func testHTTPTracesNestedNodeJSDistCalls(t *testing.T) {
@@ -1121,6 +1149,31 @@ func testHTTPTracesNestedNodeJSDistCalls(t *testing.T) {
11211149
assert.Empty(t, sd, sd.String())
11221150

11231151
children := trace.ChildrenOf(parentID)
1152+
require.GreaterOrEqual(t, len(children), 2)
1153+
1154+
res = trace.FindByOperationName("processing", "internal")
1155+
1156+
var processing *jaeger.Span
1157+
1158+
if len(res) > 0 {
1159+
for i := range res {
1160+
r := &res[i]
1161+
// Check parenthood
1162+
p, ok := trace.ParentOf(r)
1163+
1164+
if ok {
1165+
if p.TraceID == server.TraceID && p.SpanID == server.SpanID {
1166+
processing = r
1167+
break
1168+
}
1169+
}
1170+
}
1171+
}
1172+
1173+
if processing != nil {
1174+
children = trace.ChildrenOf(processing.SpanID)
1175+
}
1176+
11241177
require.Len(t, children, 3)
11251178

11261179
seenP := false

0 commit comments

Comments
 (0)