Add resource usage logging.

Add log_resource_usage, which prints the current and elapsed user and
system times. Add a usage example in packet_list_model.cpp.

Change-Id: I747161c754a3731e540821715cc9bb10b3dc821d
Reviewed-on: https://code.wireshark.org/review/16383
Petri-Dish: Gerald Combs <gerald@wireshark.org>
Tested-by: Petri Dish Buildbot <buildbot-no-reply@wireshark.org>
Reviewed-by: Gerald Combs <gerald@wireshark.org>

3 files changed, 91 insertions, 0 deletions

diff --git a/ui/qt/packet_list_model.cpp b/ui/qt/packet_list_model.cpp
index 4bbb63658d..26116b6549 100644
--- a/ui/qt/packet_list_model.cpp
+++ b/ui/qt/packet_list_model.cpp
@@ -44,6 +44,13 @@
 #include <QModelIndex>
 #include <QElapsedTimer>
 
+// Print timing information
+//#define DEBUG_PACKET_LIST_MODEL 1
+
+#ifdef DEBUG_PACKET_LIST_MODEL
+#include <wsutil/time_util.h>
+#endif
+
 PacketListModel::PacketListModel(QObject *parent, capture_file *cf) :
     QAbstractItemModel(parent),
     max_row_height_(0),
@@ -603,6 +610,12 @@ gint PacketListModel::appendPacket(frame_data *fdata)
     PacketListRecord *record = new PacketListRecord(fdata);
     gint pos = -1;
 
+#ifdef DEBUG_PACKET_LIST_MODEL
+    if (fdata->num % 10000 == 1) {
+        log_resource_usage(fdata->num == 1, "%u packets", fdata->num);
+    }
+#endif
+
     physical_rows_ << record;
 
     if (fdata->flags.passed_dfilter || fdata->flags.ref_time) {
diff --git a/wsutil/time_util.c b/wsutil/time_util.c
index fc0a187407..5f6ac8a39f 100644
--- a/wsutil/time_util.c
+++ b/wsutil/time_util.c
@@ -22,8 +22,17 @@
 
 #include "config.h"
 
+#include <glib.h>
+
 #include "time_util.h"
 
+#ifndef _WIN32
+#include <sys/time.h>
+#include <sys/resource.h>
+#else
+#include <windows.h>
+#endif
+
 /* converts a broken down date representation, relative to UTC,
  * to a timestamp; it uses timegm() if it's available.
  * Copied from Glib source gtimer.c
@@ -62,6 +71,54 @@ mktime_utc(struct tm *tm)
 #endif /* !HAVE_TIMEGM */
 }
 
+static double last_utime = 0.0;
+static double last_stime = 0.0;
+
+void log_resource_usage(gboolean reset_delta, const char *format, ...) {
+	va_list ap;
+	GString *log_str = g_string_new("");
+	double utime;
+	double stime;
+
+#ifndef _WIN32
+	struct rusage ru;
+
+	getrusage(RUSAGE_SELF, &ru);
+
+	utime = ru.ru_utime.tv_sec + (ru.ru_utime.tv_usec / 1000000.0);
+	stime = ru.ru_stime.tv_sec + (ru.ru_stime.tv_usec / 1000000.0);
+#else /* _WIN32 */
+	HANDLE h_proc = GetCurrentProcess();
+	FILETIME cft, eft, kft, uft;
+	ULARGE_INTEGER uli_time;
+
+	GetProcessTimes(h_proc, &cft, &eft, &kft, &uft);
+
+	uli_time.LowPart = uft.dwLowDateTime;
+	uli_time.HighPart = uft.dwHighDateTime;
+	utime = uli_time.QuadPart / 10000000.0;
+	uli_time.LowPart = kft.dwLowDateTime;
+	uli_time.HighPart = kft.dwHighDateTime;
+	stime = uli_time.QuadPart / 1000000000.0;
+#endif /* _WIN32 */
+
+	if (reset_delta || last_utime == 0.0) {
+		last_utime = utime;
+		last_stime = stime;
+	}
+
+	g_string_append_printf(log_str, "user %.3f +%.3f sys %.3f +%.3f ",
+		utime, utime - last_utime, stime, stime - last_stime);
+
+	va_start(ap, format);
+	g_string_append_vprintf(log_str, format, ap);
+	va_end(ap);
+
+	g_warning("%s", log_str->str);
+	g_string_free(log_str, TRUE);
+
+}
+
 /*
  * Editor modelines  -  http://www.wireshark.org/tools/modelines.html
  *
diff --git a/wsutil/time_util.h b/wsutil/time_util.h
index 37c6669b30..9f1367db2d 100644
--- a/wsutil/time_util.h
+++ b/wsutil/time_util.h
@@ -24,9 +24,30 @@
 
 #include "ws_symbol_export.h"
 
+#ifdef __cplusplus
+extern "C" {
+#endif /* __cplusplus */
+
 #include <time.h>
 
 WS_DLL_PUBLIC
 time_t mktime_utc(struct tm *tm);
 
+/** Print the process CPU time followed by a log message.
+ *
+ * Print the current process user and system CPU times along with the times
+ * elapsed since the times were last reset.
+ *
+ * @param reset_delta Reset the delta times. This will typically be TRUE when
+ * logging the first measurement and FALSE thereafter.
+ * @param format Printf-style format string. Passed to g_string_vprintf.
+ * @param ... Parameters for the format string.
+ */
+WS_DLL_PUBLIC
+void log_resource_usage(gboolean reset_delta, const char *format, ...);
+
+#ifdef __cplusplus
+}
+#endif /* __cplusplus */
+
 #endif /* __TIME_UTIL_H__ */