Implement transaction timings debug

Launch sway with SWAY_DEBUG=txn_timings to enable it.

include/sway/server.h

@@ -45,6 +45,8 @@ struct sway_server {
 	struct wlr_wl_shell *wl_shell;
 	struct wl_listener wl_shell_surface;
 
+	bool debug_txn_timings;
+
 	bool terminating;
 
 	struct sway_transaction *head_transaction; // singly linked list

sway/desktop/transaction.c

@@ -2,6 +2,7 @@
 #include <stdbool.h>
 #include <stdlib.h>
 #include <string.h>
+#include <time.h>
 #include <wlr/types/wlr_buffer.h>
 #include <wlr/types/wlr_linux_dmabuf.h>
 #include "sway/debug.h"
@@ -32,6 +33,8 @@ struct sway_transaction {
 	list_t *damage;         // struct wlr_box *
 	size_t num_waiting;
 	struct sway_transaction *next;
+	struct timespec create_time;
+	struct timespec commit_time;
 };
 
 struct sway_transaction_instruction {
@@ -48,6 +51,9 @@ struct sway_transaction *transaction_create() {
 		calloc(1, sizeof(struct sway_transaction));
 	transaction->instructions = create_list();
 	transaction->damage = create_list();
+	if (server.debug_txn_timings) {
+		clock_gettime(CLOCK_MONOTONIC, &transaction->create_time);
+	}
 	return transaction;
 }
 
@@ -177,6 +183,20 @@ void transaction_add_damage(struct sway_transaction *transaction,
  */
 static void transaction_apply(struct sway_transaction *transaction) {
 	wlr_log(L_DEBUG, "Applying transaction %p", transaction);
+	if (server.debug_txn_timings) {
+		struct timespec now;
+		clock_gettime(CLOCK_MONOTONIC, &now);
+		struct timespec *create = &transaction->create_time;
+		struct timespec *commit = &transaction->commit_time;
+		float ms_arranging = (commit->tv_sec - create->tv_sec) * 1000 +
+			(commit->tv_nsec - create->tv_nsec) / 1000000.0;
+		float ms_waiting = (now.tv_sec - commit->tv_sec) * 1000 +
+			(now.tv_nsec - commit->tv_nsec) / 1000000.0;
+		float ms_total = ms_arranging + ms_waiting;
+		wlr_log(L_DEBUG, "Transaction %p: %.1fms arranging, %.1fms waiting, "
+				"%.1fms total (%.1f frames if 60hz)", transaction,
+				ms_arranging, ms_waiting, ms_total, ms_total / (1000 / 60));
+	}
 	int i;
 	// Apply the instruction state to the container's current state
 	for (i = 0; i < transaction->instructions->length; ++i) {
@@ -271,6 +291,9 @@ void transaction_commit(struct sway_transaction *transaction) {
 		}
 		list_add(con->instructions, instruction);
 	}
+	if (server.debug_txn_timings) {
+		clock_gettime(CLOCK_MONOTONIC, &transaction->commit_time);
+	}
 	if (server.head_transaction) {
 		// There is another transaction in progress - we must add this one to
 		// the queue so we complete after it.

sway/server.c

@@ -113,6 +113,10 @@ bool server_init(struct sway_server *server) {
 		return false;
 	}
 
+	const char *debug = getenv("SWAY_DEBUG");
+	if (debug != NULL && strcmp(debug, "txn_timings") == 0) {
+		server->debug_txn_timings = true;
+	}
 	server->destroying_containers = create_list();
 
 	input_manager = input_manager_create(server);