From 92f6c6df2069577b11d3169cd6d75bb99378d36e Mon Sep 17 00:00:00 2001
From: Marek Marczykowski <marmarek@invisiblethingslab.com>
Date: Mon, 25 Feb 2013 06:48:29 +0100
Subject: [PATCH] dom0+vm/dispvm: add some timing logs

---
 dom0/restore/qfile-daemon-dvm |  6 ++++++
 dom0/restore/qubes_restore.c  |  4 +++-
 qubes_rpc/vm-file-editor.c    | 12 ++++++++++++
 3 files changed, 21 insertions(+), 1 deletion(-)

diff --git a/dom0/restore/qfile-daemon-dvm b/dom0/restore/qfile-daemon-dvm
index bebe34bf..a1369fea 100755
--- a/dom0/restore/qfile-daemon-dvm
+++ b/dom0/restore/qfile-daemon-dvm
@@ -68,6 +68,7 @@ class QfileDaemonDvm:
         if len(sys.argv) > 4 and len(sys.argv[4]) > 0:
             assert sys.argv[4] in QubesDispVmLabels.keys(), "Invalid label"
             label = QubesDispVmLabels[sys.argv[4]]
+        print >>sys.stderr, "time=%s, starting qubes_restore" % (str(time.time()))
         retcode = subprocess.call(['/usr/lib/qubes/qubes_restore',
             current_savefile,
             current_dvm_conf,
@@ -88,6 +89,7 @@ class QfileDaemonDvm:
         disp_name = f.readline().rstrip('\n')
         disptempl = f.readline().rstrip('\n')
         f.close()
+        print >>sys.stderr, "time=%s, adding to qubes.xml" % (str(time.time()))
         vm_disptempl = qvm_collection.get_vm_by_name(disptempl);
         if vm_disptempl is None:
             sys.stderr.write( 'Domain ' + disptempl + ' does not exist ?')
@@ -106,6 +108,7 @@ class QfileDaemonDvm:
         qvm_collection.save()
         qvm_collection.unlock_db()
         # Reload firewall rules
+        print >>sys.stderr, "time=%s, reloading firewall" % (str(time.time()))
         for vm in qvm_collection.values():
             if vm.is_proxyvm() and vm.is_running():
                 vm.write_iptables_xenstore_entry()
@@ -158,7 +161,9 @@ def main():
     # sys.argv[4] - override label
     # sys.argv[5] - override firewall
 
+    print >>sys.stderr, "time=%s, qfile-daemon-dvm init" % (str(time.time()))
     notify_object = dbus.SessionBus().get_object("org.freedesktop.Notifications", "/org/freedesktop/Notifications")
+    print >>sys.stderr, "time=%s, creating DispVM" % (str(time.time()))
     qfile = QfileDaemonDvm(src_vmname)
     lockf = open("/var/run/qubes/qfile-daemon-dvm.lock", 'a')
     fcntl.fcntl(lockf, fcntl.F_SETFD, fcntl.FD_CLOEXEC)
@@ -166,6 +171,7 @@ def main():
     dispname = qfile.get_dvm()
     lockf.close()
     if dispname is not None:
+        print >>sys.stderr, "time=%s, starting VM process" % (str(time.time()))
         subprocess.call(['/usr/lib/qubes/qrexec_client', '-d', dispname,
             user+':exec /usr/lib/qubes/qubes_rpc_multiplexer ' + exec_index + " " + src_vmname])
         subprocess.call(['/usr/sbin/xl', 'destroy', dispname])
diff --git a/dom0/restore/qubes_restore.c b/dom0/restore/qubes_restore.c
index f3492851..d34a45c2 100644
--- a/dom0/restore/qubes_restore.c
+++ b/dom0/restore/qubes_restore.c
@@ -476,9 +476,11 @@ int main(int argc, char **argv)
 		"time=%s, created domid=%d, creating xenstore entries\n",
 		gettime(), domid);
 	setup_xenstore(netvm_id, domid, dispid, name);
-	fprintf(stderr, "time=%s, starting qubes_guid\n", gettime());
 	rm_fast_flag();
+	fprintf(stderr, "time=%s, starting qrexec\n", gettime());
 	start_rexec(domid, default_user);
+	fprintf(stderr, "time=%s, starting qubes_guid\n", gettime());
 	start_guid(domid, argc-guid_args_start, argv+guid_args_start);
+	fprintf(stderr, "time=%s, started qubes_guid\n", gettime());
 	return 0;
 }
diff --git a/qubes_rpc/vm-file-editor.c b/qubes_rpc/vm-file-editor.c
index 4a83785a..9e372aed 100644
--- a/qubes_rpc/vm-file-editor.c
+++ b/qubes_rpc/vm-file-editor.c
@@ -8,6 +8,16 @@
 #include <ioall.h>
 #include "dvm2.h"
 
+char *gettime()
+{
+	static char retbuf[60];
+	struct timeval tv;
+	gettimeofday(&tv, NULL);
+	snprintf(retbuf, sizeof(retbuf), "%lld.%lld",
+		 (long long) tv.tv_sec, (long long) tv.tv_usec);
+	return retbuf;
+}
+
 char *get_filename()
 {
 	char buf[DVM_FILENAME_SIZE];
@@ -67,6 +77,7 @@ main()
 		perror("stat pre");
 		exit(1);
 	}
+	fprintf(stderr, "time=%s, waiting for qubes-session\n", gettime());
 	// wait for X server to starts (especially in DispVM)
 	if (stat("/tmp/qubes-session-env", &session_stat)) {
 		switch (child = fork()) {
@@ -95,6 +106,7 @@ main()
 				}
 		}
 	}
+	fprintf(stderr, "time=%s, starting editor\n", gettime());
 	switch (child = fork()) {
 		case -1:
 			perror("fork");