MMTk stats can be hard for humans to read

Andreas makes a good point about the new format not being AWK friendly. I guess a counter-point would be increased Grep friendliness which might allow more generic scripts that could be ported from one experiment to another (there is no guarantee that the Nth column will always be a particular counter, but grep'ing for a Counter name might be safer).

As an alternative it would be trivial to rework the patch so that a command line argument specified the output format (with the default being the old output format). Having just thought of this option, this would be the one I would vote for...

What do others think?

For machine readable stats there's already the xml option, so I don't think machine readability should be a major consideration here. That being said, the existing format has definitely outgrown its usefulness - it was fine when we had 6 or so counters, but not so much any more.

I originally added the xml format with the intention that it would become the canonical machine-readable format, and chose xml largely because people around me were moving that way (rather than some deep abiding attachment to the format). So if there's a desire to provide better machine-readable I'd prefer to rework the xml output, and make the human readable form as easy on the eye as possible.

I agree that the numbers are not very human readable, and could be improved. Andreas' point is key though---machine readability is the primary concern because individual runs are not particularly meaningful on their own, so in general the user will need to be pushing this through a script and aggregating/analyzing the data. However, I agree that when debugging human readability is useful. In such cases I generally resort to 'cut'

I'm happy to see it improved. Any more thoughts on what the best solution might look like?

Laurence raised the point that there is no guarantee that the Nth column will always be a particular counter, but grep'ing for a Counter name might be safer. Getting AWK to sanity-check the current column-oriented format is unfortunately not straight-forward. This definitly should be improved, as you don't want to AWK, Perl, and the like to interpret a string as numerical 0. Such a bug easily messes up your aggregates, but may go undetected for quite some time.

That being said, I agree with Steve that machine-readability is the primary goal here; you can always pipe the output through a small script to prettify it. It's the other direction that's hard. So what about the following (Tabs as \t)?

MMTk Statistics:\tGC\t7time.mu\t6872.53\ttime.gc:\t5854.95 [...] L1I_MISSES.gc\t951335255621\t(SCALED)\tTotal time\t12727.48

As the single statistics line starts with MMTk Statistics (the space is for humans; thus, AWK needs to asked to split on tabs only) it's easy to sanitze the VM's output with plain old grep. You could then process and sanity-check this with awk -F '\t':

{{$4 != "time.mu"

}}

Writing a script that turns this into output as proposed by Laurence is easy, too. The only thing that makes this task not completely straight-forward is the presence of the (SCALED) attribute, which occupies its own, out-of-order column in the above example. If, however, all statistics would get a free-text attribute (which may of course be empty, hold a unit like ms, or whatever), we had tab-separated triples all the way.

I don't understand the need for "(SCALED)". If that adjective is really required, it can be placed in the name of the value.

Hi Steve,

If you attempt to measure more events than are simultaneously supported by the underlying hardware then the kernel perf_events subsystem will multiplex the events onto the available hardware counters. The results reported by my patch are the raw event value scaled by the time it was permitted to run for. Scaled results cannot directly be compared together (as there is no guarantee that the events were running at the same time and therefore monitoring the same program behaviour). The "(SCALED)" flag is a warning that a particular counter value has been scaled in this way.

For example, measuring just one event we only need to report:

L1I_MISSES.mu: 1629940088073

However, for example on a Core 2 Duo the following three events have been multiplexed and scaled appropriately:

L1I_MISSES.mu: 1629940088073 (SCALED)
LLC_MISSES.mu: 1546188225840 (SCALED)
PERF_COUNT_HW_CACHE_L1D:MISS.mu 19434083 (SCALED)

It is feasible that some events could by multiplexed at the same time as other's being run 100% of the time therefore the "(SCALED)" flag really needs to be reported on a per counter basis.

As Daniel commented in RVM-885 some counters can be "CONTENDED" and not run at all. Rather than report a value of 0 for a counter that does not have any results (which I think would be miss leading) I choose to report it as:

L1I_MISSES.mu: CONTENDED

I look forward to your thoughts

Laurence

Hi Laurence,

Yeah, I understand how the perf counters work

I'm just talking about the formatting. We currently have a descriptive field. I was suggesting that you use that descriptive field to convey this information rather than introduce a new field to the format.

--Steve

I agree that machine-readability is the most important factor here. But I'd hope that we can come up with some format that is also easy for people to read. I think Laurence has a good point about the current stats being hard to read sometimes. Maybe they are also slightly tricky for a program to read (e.g. it must read the heading row and then use that to interpret subsequent rows). But as Steve says, cut works as well.

The problem with Andreas's solution is that it overloads tabs, using them to separate records and fields. I'd argue for a format that distinguished these, e.g. by using =s, commas and tabs.

Steve asked, why introduce a new field, e.g. ("SCALED"), rather than place it in the name of the value. I'd argue against that as SCALED is just another attribute like the value.

For example (putting spaces around \t here just to make it a little easier to read),

GC=7 \t time.mu=6872.53 \t time.gc=5854.95 \t L1I_MISSES.gc=951335255621,SCALED \t Total time=12727.48

This format is easily parsable, e.g. with 3 lines of perl. It's also amenable to cut (assuming that the order is fixed). It's pretty human readable. although output may flow over several lines on the screen), and names and other attributes are tightly tied together.

Richard

bulk defer open issues to 3.1.2

Bulk defer to 3.1.3; not essential to address for 3.1.2.

bulk defer issues to 3.1.4