Add duration of a task

[GeertvanHorrik]

What You Are Seeing?

Whenever there is a task, we have no idea how long it took, unless the script fully succeeds. A good example is this build output:

What is Expected?

The timings are only written to the output if a build succeeds. We are currently trying to optimize local builds (making them as fast as possible so devs don't have to wait too long). Therefore, it would be really nice if every task would have a duration at the end:

========================================
UpdateNuGet
========================================
Making sure NuGet is using the latest version
Checking for updates from https://www.nuget.org/api/v2/.
Currently running NuGet.exe 5.4.0.
NuGet.exe is up to date.
Updating NuGet.exe exited with '0', version is '5.4.0.6315'

========================================
RestorePackages
========================================

I would like to have a timer that writes at the end of each task:

UpdateNuGet took 5 seconds and 300 ms

What version of Cake are you using?

0.35.0

Are you running on a 32 or 64 bit system?

Irrelevant

What environment are you running on? Windows? Linux? Mac?

Irrelevant

Are you running on a CI Server? If so, which one?

Irrelevant

How Did You Get This To Happen? (Steps to Reproduce)

Irrelevant

[GeertvanHorrik]

And I am happy to contribute btw, just want to discuss this on forehand.

[patriksvensson]

@GeertvanHorrik I think this is a good idea. I would suggest that the timings would be written to the log using Diagnostic verbosity and follow the formatting in the summary report.

========================================
UpdateNuGet
========================================
Making sure NuGet is using the latest version
Checking for updates from https://www.nuget.org/api/v2/.
Currently running NuGet.exe 5.4.0.
NuGet.exe is up to date.
Updating NuGet.exe exited with '0', version is '5.4.0.6315'
Completed in 00:00:00.0019696

========================================
RestorePackages
========================================

[GeertvanHorrik]

I have implemented it as verbose, but would prefer it to be Info level so I don't have to turn on verbose for everything just to get the timings. I think it's not cluttering the logs since it's just a single line per task.

[patriksvensson]

@GeertvanHorrik

@devlead just suggested that perhaps the correct solution here instead is to output the report before the error which I think would be the best option.

Task                          Duration            
--------------------------------------------------
Setup                         00:00:02.1536645    
Foo                           00:00:00.0603488    
Bar                           00:00:09.4394936    
Baz                           00:00:45.5742178    
Corge                         ERROR (00:00:51.9932199)
Qux                           SKIPPED    
--------------------------------------------------
Total:                        00:02:18.0235864 

[GeertvanHorrik]

I would still opt for the current implementation. The reason is that while the build scripts are running, I already want to see how long a specific (completed) task took. This allows me to start improving / analyzing stuff while the script is running instead of having to wait for the full script to be completed.

[patriksvensson]

@GeertvanHorrik Then I think that the output should be info level with diagnostic verbosity (it is, after all, a diagnostic log message). When doing optimizations for something, you would just pass the diagnostic verbosity and get it in your log output.

I think this would clutter up the log if printed as information (I myself would not want to see it when running my builds).

@cake-build/cake-team What are your opinions about this?

[Roemer]

I could also use that information in many scenarios (mostly CI-based) without having a full verbose log. So I would vote for information or would it be possible to have some kind of flag like LogTimeForEachTask somewhere which could globally be set to true in Setup or something?

[Cheesebaron]

I would probably personally prefer a mix of both.

Probably something like:

• When requested (not sure if this should be through log level), output at end of each task.
• At the end of execution of script, even if a task threw an error, a report of all task durations would be nice.

This would look something like:

========================================
UpdateNuGet
========================================
Some output

Completed in 00:00:00.0019696

========================================
RestorePackages
========================================
Some other output

Completed in 00:00:10.0019696

Then at the end:

Task                          Duration            
--------------------------------------------------
Setup                         00:00:02.1536645    
Foo                           00:00:00.0603488    
Bar                           00:00:09.4394936    
Baz                           00:00:45.5742178    
Corge                         ERROR (00:00:51.9932199)
Qux                           SKIPPED    
--------------------------------------------------
Total:                        00:02:18.0235864