[help] reported timings much lower than actual wall time

[kendonB]

Help

• I understand and agree to https://books.ropensci.org/targets/help.html.

Description

I am seeing this:

● completed branch parcels_with_buildings_ee06d6d87483c72a [24.75 seconds]
▶ dispatched branch parcels_with_buildings_1c637dd74fc23564
● completed branch parcels_with_buildings_07a2f563e9791d02 [17.155 seconds]
▶ dispatched branch parcels_with_buildings_a1840b2e02947456
● completed branch parcels_with_buildings_1c637dd74fc23564 [45.802 seconds]
▶ dispatched branch parcels_with_buildings_08795200334b68fe
● completed branch parcels_with_buildings_a1840b2e02947456 [19.422 seconds]
▶ dispatched branch parcels_with_buildings_a1bae4a3193f3d55
● completed branch parcels_with_buildings_08795200334b68fe [38.886 seconds]
▶ dispatched branch parcels_with_buildings_2574d8d4e4b7b3ce
● completed branch parcels_with_buildings_a1bae4a3193f3d55 [18.778 seconds]
▶ dispatched branch parcels_with_buildings_6f4073d87c1f143a
● completed branch parcels_with_buildings_2574d8d4e4b7b3ce [37.99 seconds]
▶ dispatched branch parcels_with_buildings_32ff72979f5e436b
● completed branch parcels_with_buildings_6f4073d87c1f143a [17.086 seconds]
▶ dispatched branch parcels_with_buildings_358a9c52327f69d4
● completed branch parcels_with_buildings_32ff72979f5e436b [36.506 seconds]
▶ dispatched branch parcels_with_buildings_eb8bdbfbe1520929

but the actual time between completions is around 3-5 minutes. I presume the extra time is writing to and reading from disk.

Consider splitting those timings out or just reporting the time from the start of input target loading to the end of output disk writing?

[wlandau]

Yes, the times are just R code execution times, and the discrepancy is probably mostly due to reading/writing from disk. But there are many other places that might cause overhead, and they often happen on different processes (for example, marshaling the target in the case of storage = "main"). It would take a lot to capture all that and aggregate it in a consistent/transparent way, and I don't have plans for that.

[kendonB]

A simpler way to achieve a similar outcome could be to print the timestamp as well as the execution time in the message?