[pve-devel] [PATCH pve-http-server v2] AnyEvent: add timestamps to debug logs

[pve-devel] [PATCH pve-http-server v2] AnyEvent: add timestamps to debug logs

[Laurențiu Leahu-Vlăducu]

This helps correlate our debug logs with other log files for
easier debugging when making API calls. This might ease debugging
in our enterprise support and forum, or for external developers
who need to debug Proxmox VE.

This patch does add some delay when printing debug logs (pointed out
by Thomas):

elapsed[gettimeofday+strftime,1000000]: 5.730306 s => 5.730306 us/loop
elapsed[strftime,             1000000]: 5.532132 s => 5.532132 us/loop
elapsed[gettimeofday,         1000000]: 100.645 ms => 100.645 ns/loop

However, this only happens when printing debug logs, in which case
it is often expected that software might be slightly slower.

Signed-off-by: Laurențiu Leahu-Vlăducu <l.leahu-vladucu@proxmox.com>
Tested-by: Thomas Lamprecht <t.lamprecht@proxmox.com>
Reviewed-by: Thomas Lamprecht <t.lamprecht@proxmox.com>
---

Changes since v1:
* the separator '|' is no longer used after the timestamp
* improved commit message
* added Thomas' T-b and R-b 


 src/PVE/APIServer/AnyEvent.pm | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/src/PVE/APIServer/AnyEvent.pm b/src/PVE/APIServer/AnyEvent.pm
index 59bc184..24b298d 100644
--- a/src/PVE/APIServer/AnyEvent.pm
+++ b/src/PVE/APIServer/AnyEvent.pm
@@ -76,7 +76,9 @@ sub dprint {
 
     my ($pkg, $pkgfile, $line, $sub) = caller(1);
     $sub =~ s/^(?:.+::)+//;
-    print "worker[$$]: $pkg +$line: $sub: $message\n";
+    my ($secs, $microsecs) = gettimeofday();
+    my $timestr = strftime("%F %T", localtime($secs)) . sprintf(".%06d", $microsecs);
+    print "$timestr worker[$$]: $pkg +$line: $sub: $message\n";
 }
 
 sub log_request {
-- 
2.47.3



_______________________________________________
pve-devel mailing list
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel

Re: [pve-devel] [PATCH pve-http-server v2] AnyEvent: add timestamps to debug logs

[Thomas Lamprecht]

Am 21.10.25 um 16:12 schrieb Laurențiu Leahu-Vlăducu:
> This helps correlate our debug logs with other log files for
> easier debugging when making API calls. This might ease debugging
> in our enterprise support and forum, or for external developers
> who need to debug Proxmox VE.
> 
> This patch does add some delay when printing debug logs (pointed out
> by Thomas):
> 
> elapsed[gettimeofday+strftime,1000000]: 5.730306 s => 5.730306 us/loop
> elapsed[strftime,             1000000]: 5.532132 s => 5.532132 us/loop
> elapsed[gettimeofday,         1000000]: 100.645 ms => 100.645 ns/loop
> 
> However, this only happens when printing debug logs, in which case
> it is often expected that software might be slightly slower.
> 
> Signed-off-by: Laurențiu Leahu-Vlăducu <l.leahu-vladucu@proxmox.com>
> Tested-by: Thomas Lamprecht <t.lamprecht@proxmox.com>
> Reviewed-by: Thomas Lamprecht <t.lamprecht@proxmox.com>
> ---
> 
> Changes since v1:
> * the separator '|' is no longer used after the timestamp
> * improved commit message
> * added Thomas' T-b and R-b 

But I did not gave those trailers out, or do I overlook something?
Please do not infer such things from some reply, they need to be
stated rather explicitly (transforming a "lgtm" to a R-b or the like
can be borderline fine, but rather also not something one should
just do.

> 
> 
>  src/PVE/APIServer/AnyEvent.pm | 4 +++-
>  1 file changed, 3 insertions(+), 1 deletion(-)
> 
> diff --git a/src/PVE/APIServer/AnyEvent.pm b/src/PVE/APIServer/AnyEvent.pm
> index 59bc184..24b298d 100644
> --- a/src/PVE/APIServer/AnyEvent.pm
> +++ b/src/PVE/APIServer/AnyEvent.pm
> @@ -76,7 +76,9 @@ sub dprint {
>  
>      my ($pkg, $pkgfile, $line, $sub) = caller(1);
>      $sub =~ s/^(?:.+::)+//;
> -    print "worker[$$]: $pkg +$line: $sub: $message\n";
> +    my ($secs, $microsecs) = gettimeofday();
> +    my $timestr = strftime("%F %T", localtime($secs)) . sprintf(".%06d", $microsecs);
> +    print "$timestr worker[$$]: $pkg +$line: $sub: $message\n";
>  }
>  
>  sub log_request {



_______________________________________________
pve-devel mailing list
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel

[pve-devel] applied: [PATCH pve-http-server v2] AnyEvent: add timestamps to debug logs

[Thomas Lamprecht]

On Tue, 21 Oct 2025 16:10:30 +0200, Laurențiu Leahu-Vlăducu wrote:
> This helps correlate our debug logs with other log files for
> easier debugging when making API calls. This might ease debugging
> in our enterprise support and forum, or for external developers
> who need to debug Proxmox VE.
> 
> This patch does add some delay when printing debug logs (pointed out
> by Thomas):
> 
> [...]

Applied, with my trailers dropped, thanks!

[1/1] AnyEvent: add timestamps to debug logs
      commit: 2bf82ef2e78e1bfbd4e9de3c5c106dee5b606821


_______________________________________________
pve-devel mailing list
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel