Test time indicators in build log not showing up all the time - how to fix this?

The build log as shown on the "Build Log" tab sometimes will show a time indicator after a test in parentheses. This looks like "path/to/test.t (45s)".

I'd like to make sure these values appear for all tests, and that they're correct. We recently made some changes to run our test suite in parallel and now these indicators mostly don't appear, and when they do, they're wrong.

I'm generating testStarted and testFinished messages with timestamps, but this doesn't seem to help. here is an example message pair as taken from the agent's log/teamcity-build.log file

##teamcity[testStarted captureStandardOutput='true' name='Found at least one Feature with the name Oxford' timestamp='2016-01-04T20:44:17.198']

##teamcity[testFinished name='Found at least one Feature with the name Oxford' timestamp='2016-01-04T20:44:17.199']

So I'd like to know why TeamCity sometimes adds these indicators and sometimes doesn't so I can ensure that they always show up. I looked in the documentation for build messages, but there's nothing relevant there.

I do note that if I got the "Tests" tab for a build it does show a breakdown of every individual test sorted by duration, so clearly TC is accepting the timestamp info and doing something with it.

We're using TeamCity Professional 9.0.3 (build 32334).

Comment actions Permalink

Just to clarify, while the example test I showed took just 0.001s we do have other tests that take longer, so if TC has a threshold for when to show this, we do have plenty of tests that take 10+ seconds that still don't have the time indicators next to them.

Comment actions Permalink

A further update ... we upgraded to the latest release (TeamCity Professional 9.1.5 (build 37377)) but nothing has changed in the Build Log.

Comment actions Permalink

Hi Dave,

Sorry for the delay in replying.

TeamCity indded has a threshold on displaying the time for a test in the build log. It might be better to explore test durations ont he build's Tests tab.
Upgrade is also a right move :)

However, the note that you run tests in parallel seems important here. To make TeamCity aware of the parallel processes you will need to use "flowId" in the service messages.
That might help if you use the same flowId for the messages printed from the same "thread".
However, in the case of the test duration it should be enough to just add "duration" to the "testFinished" message that is menationed in the section.

Comment actions Permalink

Ah, I think I found the problem. We didn't know about flowId, so we were buffering parallel test output and then spitting it all out at once at the end. This seemed to confuse TC, even with timestamp values in the messages. However, it looks like with flowId we can simply remove the buffering entirely and we get accurate timings in the Build Log tab.


Please sign in to leave a comment.