Re: [PATCH] tracing: Export key trace event symbols

From: Ron Rechenmacher
Date: Tue Apr 21 2015 - 18:23:55 EST


Steven Rostedt wrote on 04/21/15 10:49:
[snip]

OK, lets see what you are doing in your patch:

Thanks for helping/discussing!


+/*
+ * Allow modules to register additional trace routines
+ */
+EXPORT_TRACEPOINT_SYMBOL_GPL(irq_handler_entry);
+EXPORT_TRACEPOINT_SYMBOL_GPL(irq_handler_exit);
+

Instead of just saying "Allow modules to register additional trace
routines", please explain what its used for. What are you measuring
externally? Just the timings of the interrupts?

How about "Allow for module (internal or external) to register trace function which
shows (or measures) interactions with user-space executables more directly. Knowing
when interrupts happen and how they can subtly impact user-space application timing
is important in some application."


I'm also curious to know why ftrace isn't good enough.

ftrace (if one considers ltt-ng) is probably capable of doing what my trace does
except that the timestamp is not TOD (Time Of Day) -- but probably/maybe could
be made to do so???

It's a matter of complexity or "start up cost" (or entry barrier).

I'm not the best at articulating all there is to TRACE succinctly, but lets
start with the fact that the user-space component of TRACE is basically just a header
file that defines the TRACE printf-like macro and handles the initialization which is
basically mmap-ing a file (as a trace buffer (with control structure)) and is,
for the most part, Unix OS independent.

The TRACE module, in addition to registering TRACE compatible tracing functions,
also creates a virtual file that the user-space TRACE-enable program(s) can mmap just
like another regular file (it doesn't know it's a kernel virtual file).
[As a side point, it's just for convenience that one or more user-space programs are
configured (via env. var.) to use the kernel virtual file as the buffer; they could use
any other regular file or each program could use a separate file.]

The module becomes critical when tracing OS key interactions (scheduling and interrupts)
with the userspace application(s) is necessary.



Maybe the better solution is to add something to ftrace that does what
your tracer currently does?

Although there is significant overlap between my TRACE and ftrace, the key
design criteria is such that trying to make ftrace do what is desired of TRACE
would be impractical. Ftrace is more of a developer tool while TRACE is more of
an end-user utility, where simplicity of use is paramount.

Thanks for your help,
Ron

PS. Below, I've included a portion of a print out from the user-space TRACE control
program printing the buffer and showing the exact impact that an interrupt
has on a program looping. Just a contrived example.


-- Steve


Thanks for you consideration and if there is specific help/suggestion you can offer to
get my patch accepted, please let me know.

Thanks again for the discussion.
/home/ron/work/tracePrj/trace
cluck :^) TRACE_SHOW=HxNTiICLR
--04/21_16:42:24--
/home/ron/work/tracePrj/trace
cluck :^) tshow 10000 | tdelta -stats | { for xx in 1 2;do read h; echo "$h";done;tail;}
idx us_tod delta tid TID cpu lv r msg
---- ---------------- --------- ----- --- --- -- - -----------------------------
9996 1429652195997224 1 40744 18 17 0 . Hello 9996. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9997 1429652195997223 1 40744 18 17 0 . Hello 9997. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9998 1429652195997222 1 40744 18 17 0 . Hello 9998. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9999 1429652195997221 1 40744 18 17 0 . Hello 9999. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
cpu="0"
min -13
max 17
tot 7872
ave 0.7872787
cnt 9999
--04/21_16:42:27--
/home/ron/work/tracePrj/trace
cluck :^) tshow 10000 | tdelta -stats | { for xx in 1 2;do read h; echo "$h";done;grep -C15 '2 17';}
idx us_tod delta tid TID cpu lv r msg
---- ---------------- --------- ----- --- --- -- - -----------------------------
9438 1429652195997676 1 40744 18 17 0 . Hello 9470. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9439 1429652195997676 0 40744 18 17 0 . Hello 9471. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9440 1429652195997675 1 40744 18 17 0 . Hello 9472. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9441 1429652195997674 1 40744 18 17 0 . Hello 9473. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9442 1429652195997673 1 40744 18 17 0 . Hello 9474. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9443 1429652195997672 1 40744 18 17 0 . Hello 9475. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9444 1429652195997672 0 40744 18 17 0 . Hello 9476. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9445 1429652195997671 1 40744 18 17 0 . Hello 9477. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9446 1429652195997670 1 40744 18 17 0 . Hello 9478. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9447 1429652195997667 3 40744 0 17 28 . sirqexit: cpu=17 vec_nr=9
9448 1429652195997664 3 40744 0 17 27 . sirqenter: cpu=17 vec_nr=9
9449 1429652195997662 2 40744 0 17 28 . sirqexit: cpu=17 vec_nr=1
9450 1429652195997660 2 40744 0 17 27 . sirqenter: cpu=17 vec_nr=1
9451 1429652195997656 4 0 0 13 28 . sirqexit: cpu=13 vec_nr=9
9452 1429652195997669 -13 40744 18 17 0 . Hello 9479. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9453 1429652195997652 17 0 0 13 27 1 sirqenter: cpu=13 vec_nr=9
9454 1429652195997652 0 40744 18 17 0 . Hello 9480. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9455 1429652195997651 1 40744 18 17 0 . Hello 9481. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9456 1429652195997649 2 0 0 13 28 1 sirqexit: cpu=13 vec_nr=1
9457 1429652195997649 0 40744 18 17 0 . Hello 9482. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9458 1429652195997648 1 0 0 12 28 . sirqexit: cpu=12 vec_nr=9
9459 1429652195997648 0 40744 18 17 0 . Hello 9483. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9460 1429652195997647 1 40744 18 17 0 . Hello 9484. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9461 1429652195997646 1 40744 18 17 0 . Hello 9485. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9462 1429652195997645 1 0 0 13 27 1 sirqenter: cpu=13 vec_nr=1
9463 1429652195997645 0 40744 18 17 0 1 Hello 9486. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9464 1429652195997644 1 0 0 12 27 . sirqenter: cpu=12 vec_nr=9
9465 1429652195997643 1 40744 18 17 0 . Hello 9487. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9466 1429652195997642 1 40744 18 17 0 . Hello 9488. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
9467 1429652195997642 0 0 0 12 28 . sirqexit: cpu=12 vec_nr=1
9468 1429652195997641 1 40744 18 17 0 . Hello 9489. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
--04/21_17:15:52--



--
Ron Rechenmacher
Engineer
Fermi National Accelerator Laboratory
Batavia, IL 60510
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/