We actually have the timestamps in the task log table, but we're not using this information right now.

The code change to display the execution time is fairly straightforward, see patch. See also hosting_task_log_with_exec_time_patch.png to see what the log looks like with the patch.

Note that this would be more useful if the theme implemented the "strong" tag, so I'll open an issue for that. I chose "~0" to mean "negligible time" to be able to more quickly tell apart long calls until we patch Eldir.

CommentFileSizeAuthor
#10 hosting_display_task_log_exec_time_v4.patch2.92 KBgboudrias
#8 hosting_display_task_log_exec_time_v3.patch2.66 KBgboudrias
hosting_task_log_with_exec_time_patch.png74.67 KBgboudrias
hosting_task_log_without_exec_time_patch.png70 KBgboudrias
hosting_display_task_log_exec_time.patch2.66 KBgboudrias
#5 hosting_display_task_log_exec_time_v2.patch2.66 KBgboudrias
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

gboudrias created an issue. See original summary.

ergonlogic’s picture

ergonlogic
he/him
Primary language English
Location Montréal, Québec 🇨🇦
CreditAttribution: ergonlogic commented

This is a neat addition. I'm not so sure about the "~0" notation though. I think "<1 s." would be more standard. That said, I think it's a bit of a distraction to mark any time on items that were sub-second in duration. So maybe just a "-" would do.

gboudrias’s picture

gboudrias CreditAttribution: gboudrias at Praxis Labs Coop commented

I agree that "-" looks cleaner, although the total number of seconds doesn't add up. I was afraid this could be seen as a bug but I don't really have an opinion one way or another.

ergonlogic’s picture

ergonlogic
he/him
Primary language English
Location Montréal, Québec 🇨🇦
CreditAttribution: ergonlogic commented

These should be Unix timestamps, and so granular to the second. I think if you just change to if ($exec_time < 1) {, they should add up properly.

gboudrias’s picture

gboudrias CreditAttribution: gboudrias at Praxis Labs Coop commented
FileSize
hosting_display_task_log_exec_time_v2.patch2.66 KB

See updated V2 patch. The seconds don't add up but after some thinking I think everyone will understand negligible time adds up.

The thing is the function call during which the second rolls over is not necessarily 1s long. I think that's the lack of granularity, since so many log entries have the same timestamp.

gboudrias’s picture

gboudrias CreditAttribution: gboudrias at Praxis Labs Coop commented
Issue tags: +Aegir 3.1
gboudrias’s picture

gboudrias CreditAttribution: gboudrias at Praxis Labs Coop commented
Status: Active » Needs review
gboudrias’s picture

gboudrias CreditAttribution: gboudrias at Praxis Labs Coop commented
FileSize
hosting_display_task_log_exec_time_v3.patch2.66 KB

Here's a compromise: use the "-" but on <= 1. I think this is the only solution that makes sense since we just can't know if a task takes a second, and it would be inaccurate to highlight certain tasks as taking more time than other based on information we don't have. The seconds don't add up no matter what.

| timestamp |
| 1437664048 |
| 1437664048 |
| 1437664048 |
| 1437664048 |
| 1437664048 |
| 1437664048 |
| 1437664048 |
| 1437664049 | <-- gets shown as 1s in previous patch
| 1437664049 |
| 1437664049 |
| 1437664049 |

If you agree I think we can just commit this.

ergonlogic’s picture

ergonlogic
he/him
Primary language English
Location Montréal, Québec 🇨🇦
CreditAttribution: ergonlogic commented

I think we should just put down '1s' when the timestamp ticks over. That way the time should add up. It'll basically be that everything with a '-' prior to it (since the last '1s') happened in that same second. We could just document that somewhere, like in a 'title' attribute for the '1s' divs.

gboudrias’s picture

gboudrias CreditAttribution: gboudrias at Praxis Labs Coop commented
FileSize
hosting_display_task_log_exec_time_v4.patch2.92 KB

Fourth time's the charm :)

I added the message to 1s entries. I suspect that the reason the total doesn't match the execution time (if you have the execution time patch) is because the exec time is calculated by comparing the time starting from the creation of the node, not the start of the first task.

In any case, the totals in hosting_task_log add up as they're shown here.

ergonlogic’s picture

ergonlogic
he/him
Primary language English
Location Montréal, Québec 🇨🇦
CreditAttribution: ergonlogic commented
Status: Needs review » Reviewed & tested by the community

Looks, good.

gboudrias’s picture

gboudrias CreditAttribution: gboudrias at Praxis Labs Coop commented
Status: Reviewed & tested by the community » Fixed

Pushed to 7.x-3.x. Thanks :)

  • gboudrias committed 21755b8 on 7.x-3.x 
    Issue #2547209 by gboudrias, ergonlogic: Display execution time in task...

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.