@@ -185,16 +185,35 @@ static void PrintElapse(std::ostream& os, int64_t cur_time,
185185
186186static void PrintAnnotations (
187187 std::ostream& os, int64_t cur_time, int64_t * last_time,
188- SpanInfoExtractor** extractors, int num_extr) {
188+ SpanInfoExtractor** extractors, int num_extr, const RpczSpan* span ) {
189189 int64_t anno_time;
190190 std::string a;
191+ const char * span_type_str = " Span" ;
192+ if (span) {
193+ switch (span->type ()) {
194+ case SPAN_TYPE_SERVER:
195+ span_type_str = " ServerSpan" ;
196+ break ;
197+ case SPAN_TYPE_CLIENT:
198+ span_type_str = " ClientSpan" ;
199+ break ;
200+ case SPAN_TYPE_BTHREAD:
201+ span_type_str = " BthreadSpan" ;
202+ break ;
203+ }
204+ }
205+
191206 // TODO: Going through all extractors is not strictly correct because
192207 // later extractors may have earlier annotations.
193208 for (int i = 0 ; i < num_extr; ++i) {
194209 while (extractors[i]->PopAnnotation (cur_time, &anno_time, &a)) {
195210 PrintRealTime (os, anno_time);
196211 PrintElapse (os, anno_time, last_time);
197- os << ' ' << WebEscape (a);
212+ os << ' ' ;
213+ if (span) {
214+ os << ' [' << span_type_str << ' ' << SPAN_ID_STR << ' =' << Hex (span->span_id ()) << " ] " ;
215+ }
216+ os << WebEscape (a);
198217 if (a.empty () || butil::back_char (a) != ' \n ' ) {
199218 os << ' \n ' ;
200219 }
@@ -204,12 +223,12 @@ static void PrintAnnotations(
204223
205224static bool PrintAnnotationsAndRealTimeSpan (
206225 std::ostream& os, int64_t cur_time, int64_t * last_time,
207- SpanInfoExtractor** extr, int num_extr) {
226+ SpanInfoExtractor** extr, int num_extr, const RpczSpan* span ) {
208227 if (cur_time == 0 ) {
209228 // the field was not set.
210229 return false ;
211230 }
212- PrintAnnotations (os, cur_time, last_time, extr, num_extr);
231+ PrintAnnotations (os, cur_time, last_time, extr, num_extr, span );
213232 PrintRealTime (os, cur_time);
214233 PrintElapse (os, cur_time, last_time);
215234 return true ;
@@ -239,9 +258,10 @@ static void PrintClientSpan(
239258 extr[num_extr++] = server_extr;
240259 }
241260 extr[num_extr++] = &client_extr;
242- // start_send_us is always set for client spans.
243- CHECK (PrintAnnotationsAndRealTimeSpan (os, span.start_send_real_us (),
244- last_time, extr, num_extr));
261+ if (!PrintAnnotationsAndRealTimeSpan (os, span.start_send_real_us (),
262+ last_time, extr, num_extr, &span)) {
263+ os << " start_send_real_us:not-set" ;
264+ }
245265 const Protocol* protocol = FindProtocol (span.protocol ());
246266 const char * protocol_name = (protocol ? protocol->name : " Unknown" );
247267 const butil::EndPoint remote_side (butil::int2ip (span.remote_ip ()), span.remote_port ());
@@ -271,12 +291,12 @@ static void PrintClientSpan(
271291 os << std::endl;
272292
273293 if (PrintAnnotationsAndRealTimeSpan (os, span.sent_real_us (),
274- last_time, extr, num_extr)) {
275- os << " Requested(" << span.request_size () << " ) [1]" << std::endl;
294+ last_time, extr, num_extr, &span )) {
295+ os << " [ClientSpan " << SPAN_ID_STR << ' = ' << Hex (span. span_id ()) << " ] Requested(" << span.request_size () << " ) [1]" << std::endl;
276296 }
277297 if (PrintAnnotationsAndRealTimeSpan (os, span.received_real_us (),
278- last_time, extr, num_extr)) {
279- os << " Received response(" << span.response_size () << " )" ;
298+ last_time, extr, num_extr, &span )) {
299+ os << " [ClientSpan " << SPAN_ID_STR << ' = ' << Hex (span. span_id ()) << " ] Received response(" << span.response_size () << " )" ;
280300 if (span.base_cid () != 0 && span.ending_cid () != 0 ) {
281301 int64_t ver = span.ending_cid () - span.base_cid ();
282302 if (ver >= 1 ) {
@@ -289,18 +309,18 @@ static void PrintClientSpan(
289309 }
290310
291311 if (PrintAnnotationsAndRealTimeSpan (os, span.start_parse_real_us (),
292- last_time, extr, num_extr)) {
293- os << " Processing the response in a new bthread" << std::endl;
312+ last_time, extr, num_extr, &span )) {
313+ os << " [ClientSpan " << SPAN_ID_STR << ' = ' << Hex (span. span_id ()) << " ] Processing the response in a new bthread" << std::endl;
294314 }
295315
296316 if (PrintAnnotationsAndRealTimeSpan (
297317 os, span.start_callback_real_us (),
298- last_time, extr, num_extr)) {
299- os << (span.async () ? " Enter user's done" : " Back to user's callsite" ) << std::endl;
318+ last_time, extr, num_extr, &span )) {
319+ os << " [ClientSpan " << SPAN_ID_STR << ' = ' << Hex (span. span_id ()) << " ] " << (span.async () ? " Enter user's done" : " Back to user's callsite" ) << std::endl;
300320 }
301321
302322 PrintAnnotations (os, std::numeric_limits<int64_t >::max (),
303- last_time, extr, num_extr);
323+ last_time, extr, num_extr, &span );
304324}
305325
306326static void PrintClientSpan (std::ostream& os,const RpczSpan& span,
@@ -318,7 +338,15 @@ static void PrintBthreadSpan(std::ostream& os, const RpczSpan& span, int64_t* la
318338 extr[num_extr++] = server_extr;
319339 }
320340 extr[num_extr++] = &client_extr;
321- PrintAnnotations (os, std::numeric_limits<int64_t >::max (), last_time, extr, num_extr);
341+
342+ // Print span id for bthread span context identification
343+ os << " [BthreadSpan " << SPAN_ID_STR << ' =' << Hex (span.span_id ());
344+ if (span.parent_span_id () != 0 ) {
345+ os << " parent_span=" << Hex (span.parent_span_id ());
346+ }
347+ os << " ] " ;
348+
349+ PrintAnnotations (os, std::numeric_limits<int64_t >::max (), last_time, extr, num_extr, &span);
322350}
323351
324352static void PrintServerSpan (std::ostream& os, const RpczSpan& span,
@@ -348,16 +376,16 @@ static void PrintServerSpan(std::ostream& os, const RpczSpan& span,
348376 os << std::endl;
349377 if (PrintAnnotationsAndRealTimeSpan (
350378 os, span.start_parse_real_us (),
351- &last_time, extr, ARRAY_SIZE (extr))) {
352- os << " Processing the request in a new bthread" << std::endl;
379+ &last_time, extr, ARRAY_SIZE (extr), &span )) {
380+ os << " [ServerSpan " << SPAN_ID_STR << ' = ' << Hex (span. span_id ()) << " ] Processing the request in a new bthread" << std::endl;
353381 }
354382
355383 bool entered_user_method = false ;
356384 if (PrintAnnotationsAndRealTimeSpan (
357385 os, span.start_callback_real_us (),
358- &last_time, extr, ARRAY_SIZE (extr))) {
386+ &last_time, extr, ARRAY_SIZE (extr), &span )) {
359387 entered_user_method = true ;
360- os << " Enter " << WebEscape (span.full_method_name ()) << std::endl;
388+ os << " [ServerSpan " << SPAN_ID_STR << ' = ' << Hex (span. span_id ()) << " ] Enter " << WebEscape (span.full_method_name ()) << std::endl;
361389 }
362390
363391 const int nclient = span.client_spans_size ();
@@ -372,22 +400,22 @@ static void PrintServerSpan(std::ostream& os, const RpczSpan& span,
372400
373401 if (PrintAnnotationsAndRealTimeSpan (
374402 os, span.start_send_real_us (),
375- &last_time, extr, ARRAY_SIZE (extr))) {
403+ &last_time, extr, ARRAY_SIZE (extr), &span )) {
376404 if (entered_user_method) {
377- os << " Leave " << WebEscape (span.full_method_name ()) << std::endl;
405+ os << " [ServerSpan " << SPAN_ID_STR << ' = ' << Hex (span. span_id ()) << " ] Leave " << WebEscape (span.full_method_name ()) << std::endl;
378406 } else {
379- os << " Responding" << std::endl;
407+ os << " [ServerSpan " << SPAN_ID_STR << ' = ' << Hex (span. span_id ()) << " ] Responding" << std::endl;
380408 }
381409 }
382410
383411 if (PrintAnnotationsAndRealTimeSpan (
384412 os, span.sent_real_us (),
385- &last_time, extr, ARRAY_SIZE (extr))) {
386- os << " Responded(" << span.response_size () << ' )' << std::endl;
413+ &last_time, extr, ARRAY_SIZE (extr), &span )) {
414+ os << " [ServerSpan " << SPAN_ID_STR << ' = ' << Hex (span. span_id ()) << " ] Responded(" << span.response_size () << ' )' << std::endl;
387415 }
388416
389417 PrintAnnotations (os, std::numeric_limits<int64_t >::max (),
390- &last_time, extr, ARRAY_SIZE (extr));
418+ &last_time, extr, ARRAY_SIZE (extr), &span );
391419}
392420
393421class RpczSpanFilter : public SpanFilter {
0 commit comments