Fix #3396. Displays the start timestamp to each task

[HereticPilgrim]

Fixes #3396

Option -v adds the task start time, while -vv displays the task start time with milliseconds accuracy

Normal

$ dep deploy
task deploy:1
[localhost] 1
task deploy:2
[localhost] 2
task deploy:3
[localhost] 3

With verbose option

$ dep deploy -v
[2023-02-03 17:39:02] task deploy:1
[localhost] 1
[2023-02-03 17:39:02] task deploy:2
[localhost] 2
[2023-02-03 17:39:02] task deploy:3
[localhost] 3

With very verbose option

$ dep deploy -vv
[2023-02-03 17:39:05.112] task deploy:1
[localhost] 1
done on localhost
done deploy:1 99ms
[2023-02-03 17:39:05.211] task deploy:2
[localhost] 2
done on localhost
done deploy:2 60ms
[2023-02-03 17:39:05.271] task deploy:3
[localhost] 3
done on localhost
done deploy:3 61ms

• [ ] Bug fix #…?

• [x] New feature?

• [ ] BC breaks?

• [ ] Tests added?

• [ ] Docs added?

  Please, regenerate docs by running next command:
  $ php bin/docgen
  

[HereticPilgrim]

When adding multiple servers, you only see when the task was started locally.

Would it be helpful for debugging / profiling if we added the start time to each task per server?

Current behavior:

$ dep deploy -vv
[2023-02-03 17:42:56.945] task deploy:1
[localhost] 1
done on localhost
[example.com] 1
done on example.com
done deploy:1 93ms
[2023-02-03 17:42:57.38] task deploy:2
[localhost] 2
done on localhost
[example.com] 2
done on example.com
done deploy:2 61ms
[2023-02-03 17:42:57.99] task deploy:3
[localhost] 3
done on localhost
[example.com] 3
done on example.com
done deploy:3 60ms

Task start time per server:

$ dep deploy -vv
task deploy:1
[2023-02-03 17:42:55.945] [localhost] 1
done on localhost
[2023-02-03 17:42:56.102] [example.com] 1
done on example.com
done deploy:1 157ms
task deploy:2
[2023-02-03 17:42:57.038] [localhost] 2
done on localhost
[2023-02-03 17:42:57.458] [example.com] 2
done on example.com
done deploy:2 420ms
task deploy:3
[2023-02-03 17:42:57.990] [localhost] 3
done on localhost
[2023-02-03 17:42:58.050] [example.com] 3
done on example.com
done deploy:3 60ms

Thoughts?

[antonmedv]

But why do we need milliseconds accuracy?

[HereticPilgrim]

But why do we need milliseconds accuracy?

Since the total duration is also displayed with millisecond accuracy (https://github.com/deployphp/deployer/blob/master/src/Executor/Messenger.php#L75), I assumed it was needed here as well. But I can see why it wouldn't be. Should I remove it?

[antonmedv]

What if we drop millisecond in total duration?

[HereticPilgrim]

I agree. I'm speaking from limited experience here since I just started using deployer. However, most deployment tasks that I've done so far take more than a few seconds, so I don't think milliseconds aren't relevant for total duration even for profiling. That's just network jitter.

Will update my code as soon as I find time.