From fbd553c528ed394144ba0f3f774a546dfb824a29 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Beat=20K=C3=BCng?= <beat-kueng@gmx.net>
Date: Tue, 24 Jul 2018 19:37:30 +0200
Subject: [PATCH] uorb tests: improve & extend latency test output

- min/max
- std dev
- number of missed updates
---
 .../uORB/uORB_tests/uORBTest_UnitTest.cpp     | 35 ++++++++++++++++---
 .../uORB/uORB_tests/uORBTest_UnitTest.hpp     |  2 +-
 2 files changed, 32 insertions(+), 5 deletions(-)

diff --git a/src/modules/uORB/uORB_tests/uORBTest_UnitTest.cpp b/src/modules/uORB/uORB_tests/uORBTest_UnitTest.cpp
index 0fbf24a19e..e4f4676905 100644
--- a/src/modules/uORB/uORB_tests/uORBTest_UnitTest.cpp
+++ b/src/modules/uORB/uORB_tests/uORBTest_UnitTest.cpp
@@ -88,9 +88,12 @@ int uORBTest::UnitTest::pubsublatency_main()
 
 	const unsigned maxruns = 1000;
 	unsigned timingsgroup = 0;
+	int current_value = t.val;
+	int num_missed = 0;
 
 	// timings has to be on the heap to keep frame size below 2048 bytes
 	unsigned *timings = new unsigned[maxruns];
+	unsigned timing_min = 9999999, timing_max = 0;
 
 	for (unsigned i = 0; i < maxruns; i++) {
 		/* wait for up to 500ms for data */
@@ -110,13 +113,24 @@ int uORBTest::UnitTest::pubsublatency_main()
 		}
 
 		if (pret < 0) {
-			warn("poll error %d, %d", pret, errno);
+			PX4_ERR("poll error %d, %d", pret, errno);
 			continue;
 		}
 
-		hrt_abstime elt = hrt_elapsed_time(&t.time);
+		num_missed += t.val - current_value - 1;
+		current_value = t.val;
+
+		unsigned elt = (unsigned)hrt_elapsed_time(&t.time);
 		latency_integral += elt;
 		timings[i] = elt;
+
+		if (elt > timing_max) {
+			timing_max = elt;
+		}
+
+		if (elt < timing_min) {
+			timing_min = elt;
+		}
 	}
 
 	orb_unsubscribe(test_multi_sub);
@@ -129,7 +143,7 @@ int uORBTest::UnitTest::pubsublatency_main()
 		FILE *f = fopen(fname, "w");
 
 		if (f == nullptr) {
-			warnx("Error opening file!\n");
+			PX4_ERR("Error opening file!");
 			delete[] timings;
 			return PX4_ERROR;
 		}
@@ -141,9 +155,22 @@ int uORBTest::UnitTest::pubsublatency_main()
 		fclose(f);
 	}
 
+
+	float std_dev = 0.f;
+	float mean = latency_integral / maxruns;
+
+	for (unsigned i = 0; i < maxruns; i++) {
+		float diff = (float)timings[i] - mean;
+		std_dev += diff * diff;
+	}
+
 	delete[] timings;
 
-	warnx("mean: %8.4f us", static_cast<double>(latency_integral / maxruns));
+	PX4_INFO("mean:    %8.4f us", static_cast<double>(mean));
+	PX4_INFO("std dev: %8.4f us", static_cast<double>(sqrtf(std_dev / (maxruns - 1))));
+	PX4_INFO("min:     %3i us", timing_min);
+	PX4_INFO("max:     %3i us", timing_max);
+	PX4_INFO("missed topic updates: %i", num_missed);
 
 	pubsubtest_passed = true;
 
diff --git a/src/modules/uORB/uORB_tests/uORBTest_UnitTest.hpp b/src/modules/uORB/uORB_tests/uORBTest_UnitTest.hpp
index fdcba194ec..3672dba3d0 100644
--- a/src/modules/uORB/uORB_tests/uORBTest_UnitTest.hpp
+++ b/src/modules/uORB/uORB_tests/uORBTest_UnitTest.hpp
@@ -153,7 +153,7 @@ int uORBTest::UnitTest::latency_test(orb_id_t T, bool print)
 
 	/* give the test task some data */
 	while (!pubsubtest_passed) {
-		t.val = 308;
+		++t.val;
 		t.time = hrt_absolute_time();
 
 		if (PX4_OK != orb_publish(T, pfd0, &t)) {