KVM: selftests: Rework debug message printing

There were a few problems with the way we output "debug" messages.
The first is that we used DEBUG() which is defined when NDEBUG is
not defined, but NDEBUG will never be defined for kselftests
because it relies too much on assert(). The next is that most
of the DEBUG() messages were actually "info" messages, which
users may want to turn off if they just want a silent test that
either completes or asserts. Finally, a debug message output from
a library function, and thus for all tests, was annoying when its
information wasn't interesting for a test.

Rework these messages so debug messages only output when DEBUG
is defined and info messages output unless QUIET is defined.
Also name the functions pr_debug and pr_info and make sure that
when they're disabled we eat all the inputs. The later avoids
unused variable warnings when the variables were only defined
for the purpose of printing.

Signed-off-by: Andrew Jones <drjones@redhat.com>
Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>

6 files changed, 54 insertions, 44 deletions

diff --git a/tools/testing/selftests/kvm/demand_paging_test.c b/tools/testing/selftests/kvm/demand_paging_test.c
index 8cdb8871e4d8..c1e326d3ed7f 100644
--- a/tools/testing/selftests/kvm/demand_paging_test.c
+++ b/tools/testing/selftests/kvm/demand_paging_test.c
@@ -36,15 +36,15 @@
 #define DEFAULT_GUEST_TEST_MEM_SIZE (1 << 30) /* 1G */
 
 #ifdef PRINT_PER_PAGE_UPDATES
-#define PER_PAGE_DEBUG(...) DEBUG(__VA_ARGS__)
+#define PER_PAGE_DEBUG(...) printf(__VA_ARGS__)
 #else
-#define PER_PAGE_DEBUG(...)
+#define PER_PAGE_DEBUG(...) _no_printf(__VA_ARGS__)
 #endif
 
 #ifdef PRINT_PER_VCPU_UPDATES
-#define PER_VCPU_DEBUG(...) DEBUG(__VA_ARGS__)
+#define PER_VCPU_DEBUG(...) printf(__VA_ARGS__)
 #else
-#define PER_VCPU_DEBUG(...)
+#define PER_VCPU_DEBUG(...) _no_printf(__VA_ARGS__)
 #endif
 
 #define MAX_VCPUS 512
@@ -165,6 +165,8 @@ static struct kvm_vm *create_vm(enum vm_guest_mode mode, int vcpus,
 		 PTES_PER_4K_PT;
 	pages = vm_adjust_num_guest_pages(mode, pages);
 
+	pr_info("Testing guest mode: %s\n", vm_guest_mode_string(mode));
+
 	vm = _vm_create(mode, pages, O_RDWR);
 	kvm_vm_elf_load(vm, program_invocation_name, 0, 0);
 #ifdef __x86_64__
@@ -192,8 +194,8 @@ static int handle_uffd_page_request(int uffd, uint64_t addr)
 
 	r = ioctl(uffd, UFFDIO_COPY, &copy);
 	if (r == -1) {
-		DEBUG("Failed Paged in 0x%lx from thread %d with errno: %d\n",
-		      addr, tid, errno);
+		pr_info("Failed Paged in 0x%lx from thread %d with errno: %d\n",
+			addr, tid, errno);
 		return r;
 	}
 
@@ -241,19 +243,19 @@ static void *uffd_handler_thread_fn(void *arg)
 		r = poll(pollfd, 2, -1);
 		switch (r) {
 		case -1:
-			DEBUG("poll err");
+			pr_info("poll err");
 			continue;
 		case 0:
 			continue;
 		case 1:
 			break;
 		default:
-			DEBUG("Polling uffd returned %d", r);
+			pr_info("Polling uffd returned %d", r);
 			return NULL;
 		}
 
 		if (pollfd[0].revents & POLLERR) {
-			DEBUG("uffd revents has POLLERR");
+			pr_info("uffd revents has POLLERR");
 			return NULL;
 		}
 
@@ -271,13 +273,12 @@ static void *uffd_handler_thread_fn(void *arg)
 		if (r == -1) {
 			if (errno == EAGAIN)
 				continue;
-			DEBUG("Read of uffd gor errno %d", errno);
+			pr_info("Read of uffd gor errno %d", errno);
 			return NULL;
 		}
 
 		if (r != sizeof(msg)) {
-			DEBUG("Read on uffd returned unexpected size: %d bytes",
-			      r);
+			pr_info("Read on uffd returned unexpected size: %d bytes", r);
 			return NULL;
 		}
 
@@ -315,14 +316,14 @@ static int setup_demand_paging(struct kvm_vm *vm,
 
 	uffd = syscall(__NR_userfaultfd, O_CLOEXEC | O_NONBLOCK);
 	if (uffd == -1) {
-		DEBUG("uffd creation failed\n");
+		pr_info("uffd creation failed\n");
 		return -1;
 	}
 
 	uffdio_api.api = UFFD_API;
 	uffdio_api.features = 0;
 	if (ioctl(uffd, UFFDIO_API, &uffdio_api) == -1) {
-		DEBUG("ioctl uffdio_api failed\n");
+		pr_info("ioctl uffdio_api failed\n");
 		return -1;
 	}
 
@@ -330,13 +331,13 @@ static int setup_demand_paging(struct kvm_vm *vm,
 	uffdio_register.range.len = len;
 	uffdio_register.mode = UFFDIO_REGISTER_MODE_MISSING;
 	if (ioctl(uffd, UFFDIO_REGISTER, &uffdio_register) == -1) {
-		DEBUG("ioctl uffdio_register failed\n");
+		pr_info("ioctl uffdio_register failed\n");
 		return -1;
 	}
 
 	if ((uffdio_register.ioctls & UFFD_API_RANGE_IOCTLS) !=
 			UFFD_API_RANGE_IOCTLS) {
-		DEBUG("unexpected userfaultfd ioctl set\n");
+		pr_info("unexpected userfaultfd ioctl set\n");
 		return -1;
 	}
 
@@ -404,8 +405,7 @@ static void run_test(enum vm_guest_mode mode, bool use_uffd,
 	guest_test_phys_mem &= ~((1 << 20) - 1);
 #endif
 
-	DEBUG("guest physical test memory offset: 0x%lx\n",
-	      guest_test_phys_mem);
+	pr_info("guest physical test memory offset: 0x%lx\n", guest_test_phys_mem);
 
 	/* Add an extra memory slot for testing demand paging */
 	vm_userspace_mem_region_add(vm, VM_MEM_SRC_ANONYMOUS,
@@ -486,7 +486,7 @@ static void run_test(enum vm_guest_mode mode, bool use_uffd,
 	sync_global_to_guest(vm, guest_page_size);
 	sync_global_to_guest(vm, vcpu_args);
 
-	DEBUG("Finished creating vCPUs and starting uffd threads\n");
+	pr_info("Finished creating vCPUs and starting uffd threads\n");
 
 	clock_gettime(CLOCK_MONOTONIC, &start);
 
@@ -495,7 +495,7 @@ static void run_test(enum vm_guest_mode mode, bool use_uffd,
 			       &vcpu_args[vcpu_id]);
 	}
 
-	DEBUG("Started all vCPUs\n");
+	pr_info("Started all vCPUs\n");
 
 	/* Wait for the vcpu threads to quit */
 	for (vcpu_id = 0; vcpu_id < vcpus; vcpu_id++) {
@@ -503,7 +503,7 @@ static void run_test(enum vm_guest_mode mode, bool use_uffd,
 		PER_VCPU_DEBUG("Joined thread for vCPU %d\n", vcpu_id);
 	}
 
-	DEBUG("All vCPU threads joined\n");
+	pr_info("All vCPU threads joined\n");
 
 	clock_gettime(CLOCK_MONOTONIC, &end);
 
@@ -519,12 +519,12 @@ static void run_test(enum vm_guest_mode mode, bool use_uffd,
 		}
 	}
 
-	DEBUG("Total guest execution time: %lld.%.9lds\n",
-	      (long long)(timespec_diff(start, end).tv_sec),
-	      timespec_diff(start, end).tv_nsec);
-	DEBUG("Overall demand paging rate: %f pgs/sec\n",
-	      guest_num_pages / ((double)timespec_diff(start, end).tv_sec +
-	      (double)timespec_diff(start, end).tv_nsec / 100000000.0));
+	pr_info("Total guest execution time: %lld.%.9lds\n",
+		(long long)(timespec_diff(start, end).tv_sec),
+		timespec_diff(start, end).tv_nsec);
+	pr_info("Overall demand paging rate: %f pgs/sec\n",
+		guest_num_pages / ((double)timespec_diff(start, end).tv_sec +
+		(double)timespec_diff(start, end).tv_nsec / 100000000.0));
 
 	ucall_uninit(vm);
 	kvm_vm_free(vm);
diff --git a/tools/testing/selftests/kvm/dirty_log_test.c b/tools/testing/selftests/kvm/dirty_log_test.c
index edc5c071bf02..a723333b138a 100644
--- a/tools/testing/selftests/kvm/dirty_log_test.c
+++ b/tools/testing/selftests/kvm/dirty_log_test.c
@@ -173,7 +173,7 @@ static void *vcpu_worker(void *data)
 		}
 	}
 
-	DEBUG("Dirtied %"PRIu64" pages\n", pages_count);
+	pr_info("Dirtied %"PRIu64" pages\n", pages_count);
 
 	return NULL;
 }
@@ -251,6 +251,8 @@ static struct kvm_vm *create_vm(enum vm_guest_mode mode, uint32_t vcpuid,
 	struct kvm_vm *vm;
 	uint64_t extra_pg_pages = extra_mem_pages / 512 * 2;
 
+	pr_info("Testing guest mode: %s\n", vm_guest_mode_string(mode));
+
 	vm = _vm_create(mode, DEFAULT_GUEST_PHY_PAGES + extra_pg_pages, O_RDWR);
 	kvm_vm_elf_load(vm, program_invocation_name, 0, 0);
 #ifdef __x86_64__
@@ -310,7 +312,7 @@ static void run_test(enum vm_guest_mode mode, unsigned long iterations,
 	guest_test_phys_mem &= ~((1 << 20) - 1);
 #endif
 
-	DEBUG("guest physical test memory offset: 0x%lx\n", guest_test_phys_mem);
+	pr_info("guest physical test memory offset: 0x%lx\n", guest_test_phys_mem);
 
 	bmap = bitmap_alloc(host_num_pages);
 	host_bmap_track = bitmap_alloc(host_num_pages);
@@ -375,9 +377,9 @@ static void run_test(enum vm_guest_mode mode, unsigned long iterations,
 	host_quit = true;
 	pthread_join(vcpu_thread, NULL);
 
-	DEBUG("Total bits checked: dirty (%"PRIu64"), clear (%"PRIu64"), "
-	      "track_next (%"PRIu64")\n", host_dirty_count, host_clear_count,
-	      host_track_next_count);
+	pr_info("Total bits checked: dirty (%"PRIu64"), clear (%"PRIu64"), "
+		"track_next (%"PRIu64")\n", host_dirty_count, host_clear_count,
+		host_track_next_count);
 
 	free(bmap);
 	free(host_bmap_track);
@@ -491,8 +493,8 @@ int main(int argc, char *argv[])
 	TEST_ASSERT(iterations > 2, "Iterations must be greater than two");
 	TEST_ASSERT(interval > 0, "Interval must be greater than zero");
 
-	DEBUG("Test iterations: %"PRIu64", interval: %"PRIu64" (ms)\n",
-	      iterations, interval);
+	pr_info("Test iterations: %"PRIu64", interval: %"PRIu64" (ms)\n",
+		iterations, interval);
 
 	srandom(time(0));
 
diff --git a/tools/testing/selftests/kvm/include/kvm_util.h b/tools/testing/selftests/kvm/include/kvm_util.h
index 1dc13bfa88b7..bc7c67913fe0 100644
--- a/tools/testing/selftests/kvm/include/kvm_util.h
+++ b/tools/testing/selftests/kvm/include/kvm_util.h
@@ -24,12 +24,6 @@ struct kvm_vm;
 typedef uint64_t vm_paddr_t; /* Virtual Machine (Guest) physical address */
 typedef uint64_t vm_vaddr_t; /* Virtual Machine (Guest) virtual address */
 
-#ifndef NDEBUG
-#define DEBUG(...) printf(__VA_ARGS__);
-#else
-#define DEBUG(...)
-#endif
-
 /* Minimum allocated guest virtual and physical addresses */
 #define KVM_UTIL_MIN_VADDR		0x2000
 
diff --git a/tools/testing/selftests/kvm/include/test_util.h b/tools/testing/selftests/kvm/include/test_util.h
index 920328ca5f7e..c921ea719ae0 100644
--- a/tools/testing/selftests/kvm/include/test_util.h
+++ b/tools/testing/selftests/kvm/include/test_util.h
@@ -19,6 +19,19 @@
 #include <fcntl.h>
 #include "kselftest.h"
 
+static inline int _no_printf(const char *format, ...) { return 0; }
+
+#ifdef DEBUG
+#define pr_debug(...) printf(__VA_ARGS__)
+#else
+#define pr_debug(...) _no_printf(__VA_ARGS__)
+#endif
+#ifndef QUIET
+#define pr_info(...) printf(__VA_ARGS__)
+#else
+#define pr_info(...) _no_printf(__VA_ARGS__)
+#endif
+
 ssize_t test_write(int fd, const void *buf, size_t count);
 ssize_t test_read(int fd, void *buf, size_t count);
 int test_seq_read(const char *path, char **bufp, size_t *sizep);
diff --git a/tools/testing/selftests/kvm/lib/aarch64/processor.c b/tools/testing/selftests/kvm/lib/aarch64/processor.c
index 216d802479dd..ba2ff3241781 100644
--- a/tools/testing/selftests/kvm/lib/aarch64/processor.c
+++ b/tools/testing/selftests/kvm/lib/aarch64/processor.c
@@ -186,7 +186,7 @@ unmapped_gva:
 
 static void pte_dump(FILE *stream, struct kvm_vm *vm, uint8_t indent, uint64_t page, int level)
 {
-#ifdef DEBUG_VM
+#ifdef DEBUG
 	static const char * const type[] = { "", "pud", "pmd", "pte" };
 	uint64_t pte, *ptep;
 
diff --git a/tools/testing/selftests/kvm/lib/kvm_util.c b/tools/testing/selftests/kvm/lib/kvm_util.c
index 67f5dc9a6a32..9e784c5ccc0a 100644
--- a/tools/testing/selftests/kvm/lib/kvm_util.c
+++ b/tools/testing/selftests/kvm/lib/kvm_util.c
@@ -155,7 +155,8 @@ struct kvm_vm *_vm_create(enum vm_guest_mode mode, uint64_t phy_pages, int perm)
 {
 	struct kvm_vm *vm;
 
-	DEBUG("Testing guest mode: %s\n", vm_guest_mode_string(mode));
+	pr_debug("%s: mode='%s' pages='%ld' perm='%d'\n", __func__,
+		 vm_guest_mode_string(mode), phy_pages, perm);
 
 	vm = calloc(1, sizeof(*vm));
 	TEST_ASSERT(vm != NULL, "Insufficient Memory");
@@ -193,8 +194,8 @@ struct kvm_vm *_vm_create(enum vm_guest_mode mode, uint64_t phy_pages, int perm)
 		kvm_get_cpu_address_width(&vm->pa_bits, &vm->va_bits);
 		TEST_ASSERT(vm->va_bits == 48, "Linear address width "
 			    "(%d bits) not supported", vm->va_bits);
-		DEBUG("Guest physical address width detected: %d\n",
-		      vm->pa_bits);
+		pr_debug("Guest physical address width detected: %d\n",
+			 vm->pa_bits);
 		vm->pgtable_levels = 4;
 #else
 		TEST_ASSERT(false, "VM_MODE_PXXV48_4K not supported on "