From 4db91b5f128f03334ec03a89eb8f56af1d698c78 Mon Sep 17 00:00:00 2001
From: Dirk Koopman <djk@tobit.co.uk>
Date: Mon, 25 Jul 2016 16:42:32 +0100
Subject: [PATCH] add timing stats to cmd spawn_cmd

---
 Changes               |  2 ++
 perl/DXCommandmode.pm | 22 ++++++++++++++++++++++
 2 files changed, 24 insertions(+)

diff --git a/Changes b/Changes
index e12b3e52..e1964270 100644
--- a/Changes
+++ b/Changes
@@ -1,3 +1,5 @@
+25Jul16=======================================================================
+1. Add some timing stats to cmd spawn_cmd.
 08Jul16=======================================================================
 1. Add latest wpxloc.raw
 2. Add CTY-2609
diff --git a/perl/DXCommandmode.pm b/perl/DXCommandmode.pm
index aef8d84c..14e0dd2c 100644
--- a/perl/DXCommandmode.pm
+++ b/perl/DXCommandmode.pm
@@ -38,6 +38,7 @@ use VE7CC;
 use DXXml;
 use AsyncMsg;
 use JSON;
+use Time::HiRes qw(gettimeofday tv_interval);
 
 use Mojo::IOLoop;
 use Mojo::IOLoop::ForkCall;
@@ -1251,6 +1252,24 @@ sub send_motd
 	$self->send_file($motd) if -e $motd;
 }
 
+sub _diffms
+{
+	return unless isdbg('chan');
+	my $call = shift;
+	my $a = shift;
+	my $b = shift || [gettimeofday];
+	my $prefix = shift;
+
+	my $secs = $b->[0] - $a->[0];
+	my $msecs = int(($b->[1] - $a->[1]) / 1000);
+
+	my $s = "forkcall stats: $call ";
+	$s .= "$prefix " if $prefix;
+	$s .= "${secs}S" if $secs;
+	$s .= "${msecs}mS";
+	dbg($s);
+}
+
 # Punt off a long running command into a separate process
 #
 # This is called from commands to run some potentially long running
@@ -1274,6 +1293,7 @@ sub spawn_cmd
 	my $prefix = delete $args{prefix};
 	my $progress = delete $args{progress};
 	my $args = delete $args{args} || [];
+	my $t0 = [gettimeofday];
 
 	no strict 'refs';
 		
@@ -1304,7 +1324,9 @@ sub spawn_cmd
 						 $dxchan->send(@res);
 					 }
 				 }
+				 _diffms($call, $t0, [gettimeofday], $prefix);
 			 });
+	
 	return @out;
 }
 
-- 
2.34.1