kernel/fiasco/src/kern/tb_entry_output.cpp

   1 IMPLEMENTATION:
   2
   3 #include <cstdarg>
   4 #include <cstdio>
   5 #include <cstdlib>
   6 #include <cstring>
   7
   8 #include "config.h"
   9 #include "jdb_symbol.h"
  10 #include "jdb_tbuf_output.h"
  11 #include "jdb_util.h"
  12 #include "static_init.h"
  13 #include "tb_entry.h"
  14 #include "thread.h"
  15
  16 static __attribute__((format(printf, 3, 4)))
  17 void
  18 my_snprintf(char *&buf, int &maxlen, const char *format, ...)
  19 {
  20   int len;
  21   va_list list;
  22
  23   if (maxlen<=0)
  24     return;
  25
  26   va_start(list, format);
  27   len = vsnprintf(buf, maxlen, format, list);
  28   va_end(list);
  29
  30   if (len<0 || len>=maxlen)
  31     len = maxlen-1;
  32
  33   buf    += len;
  34   maxlen -= len;
  35 }
  36
  37 #if 0
  38 static
  39 const char*
  40 trim(const char *s)
  41 {
  42   if (s)
  43     for (; *s==' '; s++)
  44       ;
  45   return s;
  46 }
  47 #endif
  48
  49 // timeout => x.x{
  50 static
  51 void
  52 format_timeout(Mword us, char *&buf, int &maxlen)
  53 {
  54   if (us >= 1000000000)         // =>100s
  55     my_snprintf(buf, maxlen, ">99s");
  56   else if (us >= 10000000)      // >=10s
  57     my_snprintf(buf, maxlen, "%lds", us/1000000);
  58   else if (us >= 1000000)       // >=1s
  59     my_snprintf(buf, maxlen, "%ld.%lds", us/1000000, (us%1000000)/100000);
  60   else if (us >= 10000)         // 10ms
  61     my_snprintf(buf, maxlen, "%ldm", us/1000);
  62   else if (us >= 1000)          // 1ms
  63     my_snprintf(buf, maxlen, "%ld.%ldm", us/1000, (us%1000)/100);
  64   else
  65     my_snprintf(buf, maxlen, "%ld%c", us, Config::char_micro);
  66 }
  67
  68 template< typename T >
  69 static
  70 char const *
  71 get_ipc_type(T e)
  72 {
  73   switch (e->ipc_type())
  74     {
  75     case L4_obj_ref::Ipc_call:           return "call";
  76     case L4_obj_ref::Ipc_call_ipc:       return "call ipc";
  77     case L4_obj_ref::Ipc_send:           return "send";
  78     case L4_obj_ref::Ipc_recv:           return "recv";
  79     case L4_obj_ref::Ipc_send_and_wait:  return "snd wait";
  80     case L4_obj_ref::Ipc_reply_and_wait: return "repl";
  81     case L4_obj_ref::Ipc_wait:           return "wait";
  82     default:                             return "unk ipc";
  83     }
  84 }
  85
  86 static char const * const __tag_interpreter_strings_l4re[] = {
  87     "ds", // 0
  88     "name",
  89     "parent",
  90     "goos",
  91     "ma",
  92     "rm", // 5
  93     "ev",
  94   };
  95 static char const * const __tag_interpreter_strings_fiasco[] = {
  96     "Kirq",      // -1
  97     "Kpf",
  98     "Kpreempt",
  99     "Ksysexc",
 100     "Kexc",      // -5
 101     "Ks0",
 102     0,
 103     "Kiopf",
 104     "Kcapfault",
 105     0,           // -10
 106     "Ktask",
 107     "Kthread",
 108     "Klog",
 109     "Ksched",
 110     "Kfactory",  // -15
 111     "Kvm",
 112     0,
 113     0,
 114     0,
 115     "Ksem",      // -20
 116     "Kmeta",
 117   };
 118
 119 static
 120 char const *
 121 tag_to_string(L4_msg_tag const &tag)
 122 {
 123   if (0x4000 <= tag.proto() && tag.proto() <= 0x4006)
 124     return __tag_interpreter_strings_l4re[tag.proto() - 0x4000];
 125   if (-21L <= tag.proto() && tag.proto() <= -1)
 126     return __tag_interpreter_strings_fiasco[-tag.proto() - 1];
 127   return 0;
 128 }
 129
 130 static
 131 void
 132 tag_interpreter_snprintf(char *&buf, int &maxlen, L4_msg_tag const &tag)
 133 {
 134   int len;
 135   char const *s;
 136
 137   if (maxlen<=0)
 138     return;
 139
 140   s = tag_to_string(tag);
 141   if (s)
 142     len = snprintf(buf, maxlen, "%s%04lx", s, tag.raw() & 0xffff);
 143   else
 144     len = snprintf(buf, maxlen, L4_PTR_FMT, tag.raw());
 145
 146   if (len<0 || len>=maxlen)
 147     len = maxlen-1;
 148
 149   buf    += len;
 150   maxlen -= len;
 151 }
 152
 153 // ipc / irq / shortcut success
 154 static
 155 unsigned
 156 formatter_ipc(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 157               char *buf, int maxlen)
 158 {
 159   Tb_entry_ipc *e = static_cast<Tb_entry_ipc*>(tb);
 160   unsigned char type = e->ipc_type();
 161   if (!type)
 162     type = L4_obj_ref::Ipc_call_ipc;
 163
 164   // ipc operation / shortcut succeeded/failed
 165   const char *m = get_ipc_type(e);
 166
 167   my_snprintf(buf, maxlen, "%s: ", (e->type()==Tbuf_ipc) ? "ipc" : "sc ");
 168   my_snprintf(buf, maxlen, "%s%-*s %s->",
 169       /*e->dst().next_period() ? "[NP] " :*/ "", tidlen, tidstr, m);
 170
 171   // print destination id
 172   if (e->dst().invalid())
 173     my_snprintf(buf, maxlen, "[C:INV] DID=%lx", e->dbg_id());
 174   else
 175     my_snprintf(buf, maxlen, "[C:%lx] DID=%lx", e->dst().raw(), e->dbg_id());
 176
 177   my_snprintf(buf, maxlen, " L=%lx", e->label());
 178
 179   // print mwords if have send part
 180   if (type & L4_obj_ref::Ipc_send)
 181     {
 182       my_snprintf(buf, maxlen, " [");
 183
 184       tag_interpreter_snprintf(buf, maxlen, e->tag());
 185
 186       my_snprintf(buf, maxlen, "] ("L4_PTR_FMT","L4_PTR_FMT")",
 187                                e->dword(0), e->dword(1));
 188     }
 189
 190   my_snprintf(buf, maxlen, " TO=");
 191   L4_timeout_pair to = e->timeout();
 192   if (type & L4_obj_ref::Ipc_send)
 193     {
 194       if (to.snd.is_absolute())
 195         {
 196           // absolute send timeout
 197           Unsigned64 end = 0; // FIXME: to.snd.microsecs_abs (e->kclock());
 198           format_timeout((Mword)(end > e->kclock() ? end-e->kclock() : 0),
 199                          buf, maxlen);
 200         }
 201       else
 202         {
 203           // relative send timeout
 204           if (to.snd.is_never())
 205             my_snprintf(buf, maxlen, "INF");
 206           else if (to.snd.is_zero())
 207             my_snprintf(buf, maxlen, "0");
 208           else
 209             format_timeout((Mword)to.snd.microsecs_rel(0), buf, maxlen);
 210         }
 211     }
 212   if (type & L4_obj_ref::Ipc_send
 213       && type & L4_obj_ref::Ipc_recv)
 214     my_snprintf(buf, maxlen, "/");
 215   if (type & L4_obj_ref::Ipc_recv)
 216     {
 217       if (to.rcv.is_absolute())
 218         {
 219           // absolute receive timeout
 220           Unsigned64 end = 0; // FIXME: to.rcv.microsecs_abs (e->kclock());
 221           format_timeout((Mword)(end > e->kclock() ? end-e->kclock() : 0),
 222                          buf, maxlen);
 223         }
 224       else
 225         {
 226           // relative receive timeout
 227           if (to.rcv.is_never())
 228             my_snprintf(buf, maxlen, "INF");
 229           else if (to.rcv.is_zero())
 230             my_snprintf(buf, maxlen, "0");
 231           else
 232             format_timeout((Mword)to.rcv.microsecs_rel(0), buf, maxlen);
 233         }
 234     }
 235 #if 0
 236   if (e->dst().next_period())
 237     my_snprintf(buf, maxlen, " left:%lld",
 238                 (Unsigned64)e->dword(0) + ((Unsigned64)e->dword(1) << 32));
 239 #endif
 240
 241   return maxlen;
 242 }
 243
 244 #if 0
 245 // short-cut ipc operation failed
 246 static
 247 unsigned
 248 formatter_sc_failed(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 249                     char *buf, int maxlen)
 250 {
 251   Tb_entry_ipc_sfl *e = static_cast<Tb_entry_ipc_sfl*>(tb);
 252   const char *m;
 253 #if 0
 254   my_snprintf(buf, maxlen, "!sc: %-*s ", tidlen, tidstr);
 255
 256   if (!e->dst().is_nil())
 257     m = (e->rcv_desc().has_receive())
 258       ? (e->rcv_desc().open_wait()) ? "repl->" : "call->"
 259       : "snd->";
 260   else
 261     m = (e->rcv_desc().open_wait()) ? "waits" : "recv from";
 262
 263   my_snprintf(buf, maxlen, "%s", m);
 264
 265   // print dst id
 266   if (!(e->rcv_desc().open_wait()) || (e->snd_desc().has_snd()))
 267     {
 268       if (e->dst().is_nil())
 269         my_snprintf(buf, maxlen, " -");
 270       else if (e->dst().is_irq())
 271         my_snprintf(buf, maxlen, " irq %02lx", e->dst().irq());
 272       else
 273         my_snprintf(buf, maxlen, " %x.%02x",
 274             e->dst().task(), e->dst().lthread());
 275     }
 276
 277   my_snprintf(buf, maxlen, " @ "L4_PTR_FMT" (rsn: ", e->ip());
 278
 279   m = "unknown";
 280
 281   if (e->dst_ok())
 282     m = "!dest sender_ok";
 283   else if (e->dst_lck())
 284     m = "dest locked";
 285   else if (!e->snd_desc().has_snd())
 286     m = "no send";
 287   else if (e->snd_desc().is_long_ipc())
 288     m = "long send";
 289   else if (e->dst().is_invalid())
 290     m = "dest invalid";
 291   else if (e->dst().is_nil())
 292     m = "dest nil";
 293 #if 0
 294   else if (e->dst().next_period())
 295     m = "next period";
 296 #endif
 297   else if (e->rcv_desc().has_receive())
 298     {
 299       if (!e->rcv_desc().is_register_ipc())
 300         m = "long recv";
 301       else if (e->snd_desc().noswitch())
 302         m = "don't switch to recv";
 303       else if (!e->timeout().rcv.is_never() && !e->timeout().rcv.is_zero())
 304         m = "to != (0, inf)";
 305       else if (e->rcv_desc().open_wait())
 306         {
 307           if (e->is_irq())
 308             m = "irq attached";
 309           else if (e->snd_lst())
 310             m = "sender queued";
 311         }
 312     }
 313
 314   my_snprintf(buf, maxlen, "%s)", m);
 315 #endif
 316   return maxlen;
 317 }
 318 #endif
 319 // result of ipc
 320 static
 321 unsigned
 322 formatter_ipc_res(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 323                   char *buf, int maxlen)
 324 {
 325   Tb_entry_ipc_res *e = static_cast<Tb_entry_ipc_res*>(tb);
 326   L4_error error;
 327   if (e->tag().has_error())
 328     error = e->result();
 329   else
 330     error = L4_error::None;
 331   const char *m = "answ"; //get_ipc_type(e);
 332
 333   my_snprintf(buf, maxlen, "     %s%-*s %s [%08lx] L=%lx err=%lx (%s) (%lx,%lx) ",
 334                             e->is_np() ? "[np] " : "",
 335                             tidlen, tidstr, m, e->tag().raw(), e->from(),
 336                             error.raw(), error.str_error(), e->dword(0),
 337                             e->dword(1));
 338
 339   return maxlen;
 340 }
 341
 342 IMPLEMENTATION:
 343
 344 #include "kobject_dbg.h"
 345
 346 // pagefault
 347 static
 348 unsigned
 349 formatter_pf(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 350              char *buf, int maxlen)
 351 {
 352   Tb_entry_pf *e = static_cast<Tb_entry_pf*>(tb);
 353   char ip_buf[32];
 354
 355   snprintf(ip_buf, sizeof(ip_buf), L4_PTR_FMT, e->ip());
 356   my_snprintf(buf, maxlen, "pf:  %-*s pfa="L4_PTR_FMT" ip=%s (%c%c) spc=%p",
 357       tidlen, tidstr, e->pfa(), e->ip() ? ip_buf : "unknown",
 358       !PF::is_read_error(e->error()) ? (e->error() & 4 ? 'w' : 'W')
 359                                      : (e->error() & 4 ? 'r' : 'R'),
 360       !PF::is_translation_error(e->error()) ? 'p' : '-',
 361       e->space());
 362
 363   return maxlen;
 364 }
 365
 366 // pagefault result
 367 static
 368 unsigned
 369 formatter_pf_res(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 370                  char *buf, int maxlen)
 371 {
 372   Tb_entry_pf_res *e = static_cast<Tb_entry_pf_res*>(tb);
 373
 374   // e->ret contains only an error code
 375   // e->err contains only up to 3 dwords
 376   my_snprintf(buf, maxlen, "     %-*s pfa="L4_PTR_FMT" dope=%02lx (%s%s) "
 377                 "err=%04lx (%s%s)",
 378               tidlen, tidstr, e->pfa(),
 379               e->ret().raw(), e->ret().error() ? "L4_IPC_" : "",
 380               e->ret().str_error(),
 381               e->err().raw(), e->err().error() ? "L4_IPC_" : "",
 382               e->err().str_error());
 383
 384   return maxlen;
 385 }
 386
 387 // kernel event (enter_kdebug("*..."))
 388 static
 389 unsigned
 390 formatter_ke(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 391              char *buf, int maxlen)
 392 {
 393   Tb_entry_ke *e = static_cast<Tb_entry_ke*>(tb);
 394   char ip_buf[32];
 395
 396   snprintf(ip_buf, sizeof(ip_buf), " @ "L4_PTR_FMT, e->ip());
 397   my_snprintf(buf, maxlen, "ke:  %-*s \"%s\"%s",
 398       tidlen, tidstr, e->msg(), e->ip() ? ip_buf : "");
 399
 400   return maxlen;
 401 }
 402
 403 // kernel event (enter_kdebug_verb("*+...", val1, val2, val3))
 404 static
 405 unsigned
 406 formatter_ke_reg(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 407                  char *buf, int maxlen)
 408 {
 409   Tb_entry_ke_reg *e = static_cast<Tb_entry_ke_reg*>(tb);
 410
 411   char ip_buf[32];
 412   snprintf(ip_buf, sizeof(ip_buf), " @ "L4_PTR_FMT, e->ip());
 413   my_snprintf(buf, maxlen, "ke:  %-*s \"%s\" "
 414       L4_PTR_FMT" "L4_PTR_FMT" "L4_PTR_FMT"%s",
 415       tidlen, tidstr, e->msg(), e->val1(), e->val2(), e->val3(),
 416       e->ip() ? ip_buf : "");
 417
 418   return maxlen;
 419 }
 420
 421
 422 // breakpoint
 423 static
 424 unsigned
 425 formatter_bp(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 426              char *buf, int maxlen)
 427 {
 428   Tb_entry_bp *e = static_cast<Tb_entry_bp*>(tb);
 429
 430   my_snprintf(buf, maxlen, "b%c:  %-*s @ "L4_PTR_FMT" ",
 431       "iwpa"[e->mode() & 3], tidlen, tidstr, e->ip());
 432   switch (e->mode() & 3)
 433     {
 434     case 1:
 435     case 3:
 436       switch (e->len())
 437         {
 438         case 1:
 439           my_snprintf(buf, maxlen, "["L4_PTR_FMT"]=%02lx",
 440                       e->addr(), e->value());
 441           break;
 442         case 2:
 443           my_snprintf(buf, maxlen, "["L4_PTR_FMT"]=%04lx",
 444                       e->addr(), e->value());
 445           break;
 446         case 4:
 447           my_snprintf(buf, maxlen, "["L4_PTR_FMT"]="L4_PTR_FMT,
 448                       e->addr(), e->value());
 449           break;
 450         }
 451       break;
 452     case 2:
 453       my_snprintf(buf, maxlen, "["L4_PTR_FMT"]", e->addr());
 454       break;
 455     }
 456
 457   return maxlen;
 458 }
 459
 460 // context switch
 461 static
 462 unsigned
 463 formatter_ctx_switch(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 464                      char *buf, int maxlen)
 465 {
 466   char symstr[24], spcstr[16] = "";
 467   Tb_entry_ctx_sw *e = static_cast<Tb_entry_ctx_sw*>(tb);
 468
 469   Context   *sctx    = 0;
 470   Mword sctxid = ~0UL;
 471   Mword src;
 472   Mword dst;
 473   Mword dst_orig;
 474
 475   if (Jdb_util::is_mapped(e->from_sched())
 476       && Jdb_util::is_mapped(e->from_sched()->context()))
 477     {
 478       sctx = e->from_sched()->context();
 479       sctxid = Thread::lookup(sctx)->dbg_info()->dbg_id();
 480     }
 481
 482   src = static_cast<Thread const *>(e->ctx())->dbg_info()->dbg_id();
 483   dst = static_cast<Thread const *>(e->dst())->dbg_info()->dbg_id();
 484   dst_orig = static_cast<Thread const *>(e->dst_orig())->dbg_info()->dbg_id();
 485
 486   Address addr       = e->kernel_ip();
 487
 488   if (!Jdb_symbol::match_addr_to_symbol_fuzzy(&addr, 0 /*kernel*/,
 489                                               symstr, sizeof(symstr)))
 490     snprintf(symstr, sizeof(symstr), L4_PTR_FMT, e->kernel_ip());
 491
 492   my_snprintf(buf, maxlen, "     %-*s%s '%02lx",
 493       tidlen, tidstr, spcstr, e->from_prio());
 494   if (sctx != e->ctx())
 495     my_snprintf(buf, maxlen, "(%lx)", sctxid);
 496
 497   my_snprintf(buf, maxlen, " ==> %lx ", dst);
 498
 499   if (dst != dst_orig || e->lock_cnt())
 500     my_snprintf(buf, maxlen, "(");
 501
 502   if (dst != dst_orig)
 503     my_snprintf(buf, maxlen, "want %lx",
 504         dst_orig);
 505
 506   if (dst != dst_orig && e->lock_cnt())
 507     my_snprintf(buf, maxlen, " ");
 508
 509   if (e->lock_cnt())
 510     my_snprintf(buf, maxlen, "lck %ld", e->lock_cnt());
 511
 512   if (dst != dst_orig || e->lock_cnt())
 513     my_snprintf(buf, maxlen, ") ");
 514
 515   my_snprintf(buf, maxlen, " krnl %s", symstr);
 516
 517   return maxlen;
 518 }
 519
 520
 521 // trap
 522 static
 523 unsigned
 524 formatter_trap(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 525                char *buf, int maxlen)
 526 {
 527   Tb_entry_trap *e = static_cast<Tb_entry_trap*>(tb);
 528
 529   if (!e->cs())
 530     my_snprintf(buf, maxlen, "#%02x: %-*s err=%08x @ "L4_PTR_FMT,
 531                 e->trapno(), tidlen, tidstr, e->error(), e->ip());
 532   else
 533     my_snprintf(buf, maxlen,
 534                 e->trapno() == 14
 535                   ? "#%02x: %-*s err=%04x @ "L4_PTR_FMT
 536                     " cs=%04x sp="L4_PTR_FMT" cr2="L4_PTR_FMT
 537                   : "#%02x: %-*s err=%04x @ "L4_PTR_FMT
 538                     " cs=%04x sp="L4_PTR_FMT" eax="L4_PTR_FMT,
 539                 e->trapno(),
 540                 tidlen, tidstr, e->error(), e->ip(), e->cs(), e->sp(),
 541                 e->trapno() == 14 ? e->cr2() : e->eax());
 542
 543   return maxlen;
 544 }
 545
 546 // sched
 547 static
 548 unsigned
 549 formatter_sched(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 550                 char *buf, int maxlen)
 551 {
 552   Tb_entry_sched *e = static_cast<Tb_entry_sched*>(tb);
 553   Thread const *_t = Thread::lookup (e->owner());
 554   Mword t = ~0UL;
 555   if (Jdb_util::is_mapped(_t))
 556     t = _t->dbg_info()->dbg_id();
 557
 558
 559   my_snprintf (buf, maxlen,
 560             "%-*s (ts %s) owner:%lx id:%2x, prio:%2x, left:%6ld/%-6lu",
 561                tidlen, tidstr,
 562                e->mode() == 0 ? "save" :
 563                e->mode() == 1 ? "load" :
 564                e->mode() == 2 ? "invl" : "????",
 565                t,
 566                e->id(), e->prio(), e->left(), e->quantum());
 567
 568   return maxlen;
 569 }
 570
 571 // preemption
 572 static
 573 unsigned
 574 formatter_preemption(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 575                      char *buf, int maxlen)
 576 {
 577   Tb_entry_preemption *e = static_cast<Tb_entry_preemption*>(tb);
 578   Mword t = e->preempter();
 579
 580   my_snprintf(buf, maxlen,
 581              "pre: %-*s sent to %lx",
 582              tidlen, tidstr, t);
 583
 584   return maxlen;
 585 }
 586
 587 // kernel event log binary data
 588 static
 589 unsigned
 590 formatter_ke_bin(Tb_entry *tb, const char *tidstr, unsigned tidlen,
 591                  char *buf, int maxlen)
 592 {
 593   Tb_entry_ke_bin *e = static_cast<Tb_entry_ke_bin*>(tb);
 594   char ip_buf[32];
 595
 596   snprintf(ip_buf, sizeof(ip_buf), " @ "L4_PTR_FMT, e->ip());
 597   my_snprintf(buf, maxlen, "ke:  %-*s BINDATA %s",
 598               tidlen, tidstr, e->ip() ? ip_buf : "");
 599
 600   return maxlen;
 601 }
 602
 603 STATIC_INITIALIZER(init_formatters);
 604
 605 // register all available format functions
 606 static FIASCO_INIT
 607 void
 608 init_formatters()
 609 {
 610   Jdb_tbuf_output::register_ff(Tbuf_pf, formatter_pf);
 611   Jdb_tbuf_output::register_ff(Tbuf_pf_res, formatter_pf_res);
 612   Jdb_tbuf_output::register_ff(Tbuf_ipc, formatter_ipc);
 613   Jdb_tbuf_output::register_ff(Tbuf_ipc_res, formatter_ipc_res);
 614   Jdb_tbuf_output::register_ff(Tbuf_ke, formatter_ke);
 615   Jdb_tbuf_output::register_ff(Tbuf_ke_reg, formatter_ke_reg);
 616   Jdb_tbuf_output::register_ff(Tbuf_shortcut_succeeded, formatter_ipc);
 617   Jdb_tbuf_output::register_ff(Tbuf_context_switch, formatter_ctx_switch);
 618   Jdb_tbuf_output::register_ff(Tbuf_breakpoint, formatter_bp);
 619   Jdb_tbuf_output::register_ff(Tbuf_trap, formatter_trap);
 620   Jdb_tbuf_output::register_ff(Tbuf_sched, formatter_sched);
 621   Jdb_tbuf_output::register_ff(Tbuf_preemption, formatter_preemption);
 622   Jdb_tbuf_output::register_ff(Tbuf_ke_bin, formatter_ke_bin);
 623 }