travis-ci/travis-build — pull request #199 by lukesarnacki (2014-02-02 22:05:14+00:00)
Title: Adds travis_time tags to logs [WIP]

This adds `travis_time:start` and `travis_time:end:s=0.01:u=0.01:r=0.01` tags to logs. This is marked as WIP because it is more like proof of concept which I would like to discuss. It was much harder to do for me than I expected and I would love to hear, if you also think that this is the way to go.

All commands with `echo` and `timing` are wrapped in `time` block and wrapped in `travis_time` tags:

```bash
echo -en 'travis_time:start:\r'
echo \$\ git\ fetch\ origin
{ time
travis_retry git fetch origin;
} 2> /tmp/timing.out
travis_assert
echo -en 'travis_time:end:`cat /tmp/timing.out`\r'
```

On the beginning I wanted to make time one line but it broke almost all of the tests, so for now there are new line to avoid this. I am wondering if I should make it one line or just change matchers.

When command is finished, time is saved to timing.out file in `u=%U:r=%E:s=%S` format (it is set in environment variable `TIMEFORMAT="u=%U:r=%E:s=%S"`). Then on `travis_time:end` tag its content is added using `cat` command.

I am not sure if we need two tags, but I don't think that there is other way for knowing on what line command was displayed since we know time after output is printed. So basically time label in travis web would be shown where starting tag is but time would be taken from ending tag.

I hope that I will proceed much faster with this feature from this point. Please let me know if you think that there is better way or if there is some hole in my logic. I will try to run travis locally soon and check this using `travis-web` (right now I am assuming that it will be possible to use it looking at how fold tags look like).