timem to output all samples as JSON

[hidmic]

Pretty much what the title says. As of today, timem only writes the last sample to its JSON output file, and while it can be instructed to log every sample by turning up verbosity, it does so in a non-structured way which makes it hard for downstream tooling to pick it up.

So how about populating "timem"array with all samples (on request)? It appears to me that tim::cereal::PrettyJSONOutputArchive can be told to output an array. Serializing on timem_tuple::sample would be straightforward, although writes or exits from signal handlers would no longer be possible (as the archive's destructor must be invoked and the output file flushed or the resulting JSON will be broken).

I also understand timem is there to demonstrate some of timemory's (many) features, and perhaps this works against that. Not sure. I just wanted to bring this up before I roll out a timem variation of my own.

[jrmadsen]

So how about populating "timem"array with all samples (on request)?

The primary problem here is "all". You are right that writing to JSON serialization the same way as the text log is more complicated. The reason that "all" is a problem is that "all" would essentially require dynamic memory allocation in the sample member function (or a relatively complex buffering system to avoid it). Since that function is called from a signal handler, a long running application would have a high probability of overflowing the signal stack.

However, adding support for something like --collect N where N is a max number of samples to store (allowing timem to preallocate the memory) is relatively trivial. It took me about 30-45 minutes to get a prototype working, the only issue at this point is coming up with an algorithm for evenly discarding samples once the sample buffer is full.

[hidmic]

The reason that "all" is a problem is that "all" would essentially require dynamic memory allocation in the sample member function (or a relatively complex buffering system to avoid it). Since that function is called from a signal handler, a long running application would have a high probability of overflowing the signal stack.

Yeah, I was hoping we could write samples to file as they come. It does require some care on the way out, if at all possible (e.g. no chance to be careful if the process gets SIGKILL'd). Perhaps such a feature requires a format supporting multiple consecutive documents on the same file, like YAML.

the only issue at this point is coming up with an algorithm for evenly discarding samples once the sample buffer is full.

You clearly know better than me, but still. If we were to assume the user will choose a buffer size such that no buffer overrun ever occurs, then there's no need for a clever algorithm to circumvent user error. Warn them once and pop the oldest. Alternatively, there could be more than one output file. When the buffer fills up, write it out to the Nth output file (e.g. timem_output.N.json). There's a tricky interplay there between buffer size, sampling frequency, and I/O latency that could make the write() fail. Hard to say how frequent that'd be.

[jrmadsen]

I've got a workaround with a background thread where the sample function just signals to the thread to wake, move the buffer into its own memory allocation, and clear the buffer. I'll upload the branch shortly and have you test it out.

[jrmadsen]

@hidmic test out #228 and let me know how it works for you.

[jrmadsen]

Using -b without a value defaults to a buffer size of 500. And as you can see below, adjusting the sampler frequency (i.e. -f 500) increases the number of samples.

$ ./timem -o timem-history -b -q -- sleep 10 
[sleep]> Outputting 'timem-history.json'...

$ grep -c 'sample_timestamp' timem-history.json
9

$ ./timem -o timem-history -b -f 500 -q -- sleep 10
[sleep]> Outputting 'timem-history.json'...

$ grep -c 'sample_timestamp' timem-history.json
4999

[jrmadsen]

Sample JSON:

{
 "timemory": {
  "command_line": [
   "./timem",
   "sleep",
   "10"
  ],
  "config": {
   "use_shell": false,
   "use_mpi": false,
   "use_papi": true,
   "use_sample": true,
   "debug": false,
   "verbose": -1,
   "shell": "/bin/bash",
   "shell_flags": "",
   "sample_freq": 500.0,
   "sample_delay": 0.000001,
   "buffer_size": 500
  },
  "timem": [
   {
    "wall_clock": {
     "value": 9.609806793,
     "repr": 9.609806793,
     "laps": 5000,
     "unit_value": 1,
     "unit_repr": "sec"
    },
    "user_clock": {
     "value": 0.0,
     "repr": 0.0,
     "laps": 5000,
     "unit_value": 1,
     "unit_repr": "sec"
    },

    ...

    "history": [
     {
      "sample_timestamp": {
       "localtime": "Mon Sep 27 21:53:02 2021 CDT",
       "time_since_epoch": 1632797582273282394
      },
      "wall_clock": {
       "value": 0.002000507,
       "repr": 0.002000507,
       "laps": 1,
       "unit_value": 1,
       "unit_repr": "sec"
      },
      "user_clock": {
       "value": 0.0,
       "repr": 0.0,
       "laps": 0,
       "unit_value": 1,
       "unit_repr": ""
      },
      ...

[hidmic]

Sorry for the delay. It works like a charm @jrmadsen! Thank you.