core-log: change semantics of pr_lock/unlock

The lock/unlock was intended to stop intermingled writes from
different stressors occurring.  This used a spin lock which causes
a lot of locking contention when running many stressor instances and
this can add large run time delays when stressors rush to write
termination messages at the end of run. A better strategy is to
change the semantics of pr_lock/unlock to pr_block begin/end to
indicate where a block of writes should be written out atomically
with a single write call. The block begin starts buffering messages
and the block end flushes out the buffered messages in one large
write where possible. If buffers cannot be allocated we fall back
to single writes and break the block buffering.

Signed-off-by: Colin Ian King <colin.i.king@gmail.com>

core-log.h

@@ -21,10 +21,8 @@
 
 #include "core-attribute.h"
 
-extern void pr_lock_init(void);
-extern void pr_lock(void);
-extern void pr_unlock(void);
-extern void pr_lock_exited(const pid_t pid);
+extern void pr_block_begin(void);
+extern void pr_block_end(void);
 extern void pr_fail_check(int *const rc);
 extern int pr_yaml(FILE *fp, const char *const fmt, ...) FORMAT(printf, 2, 3);
 extern void pr_closelog(void);

core-vmstat.c

@@ -1101,7 +1101,7 @@ void stress_vmstat_start(void)
 
 			stress_get_vmstat(&vmstat);
 
-			pr_lock();
+			pr_block_begin();
 			if (vmstat_count == 0)
 				pr_inf("vmstat: %3s %3s %9s %9s %9s %9s "
 					"%4s %4s %6s %6s %4s %4s %2s %2s "
@@ -1137,7 +1137,7 @@ void stress_vmstat_start(void)
 				100.0 * (double)vmstat.idle_time / clk_tick_vmstat_delay,
 				100.0 * (double)vmstat.wait_time / clk_tick_vmstat_delay,
 				100.0 * (double)vmstat.stolen_time / clk_tick_vmstat_delay);
-			pr_unlock();
+			pr_block_end();
 
 			vmstat_count++;
 			if (vmstat_count >= 25)
@@ -1171,7 +1171,7 @@ void stress_vmstat_start(void)
 					(void)snprintf(cpuspeed, sizeof(cpuspeed), "%5.5s %5.5s %5.5s",
 						" n/a ", " n/a ", " n/a ");
 
-				pr_lock();
+				pr_block_begin();
 				if (thermalstat_count == 0)
 					pr_inf("therm: AvGHz MnGHz MxGHz  LdA1  LdA5 LdA15 %s\n", therms);
 
@@ -1188,7 +1188,7 @@ void stress_vmstat_start(void)
 					pr_inf("therm: %5s %5.2f %5.2f %5.2f %s\n",
 						cpuspeed, min1, min5, min15, therms);
 				}
-				pr_unlock();
+				pr_block_end();
 				free(therms);
 
 				thermalstat_count++;
@@ -1205,7 +1205,7 @@ void stress_vmstat_start(void)
 
 			stress_get_iostat(iostat_name, &iostat);
 
-			pr_lock();
+			pr_block_begin();
 			if (iostat_count == 0)
 				pr_inf("iostat: Inflght   Rd K/s   Wr K/s Dscd K/s     Rd/s     Wr/s   Dscd/s\n");
 
@@ -1218,7 +1218,7 @@ void stress_vmstat_start(void)
 				(double)iostat.read_io * clk_scale,
 				(double)iostat.write_io * clk_scale,
 				(double)iostat.discard_io * clk_scale);
-			pr_unlock();
+			pr_block_end();
 
 			iostat_count++;
 			if (iostat_count >= 25)

stress-af-alg.c

@@ -794,15 +794,15 @@ static int stress_af_alg(const stress_args_t *args)
 	stress_af_alg_count_crypto(&count, &internal);
 
 	if (args->instance == 0) {
-		pr_lock();
+		pr_block_begin();
 		pr_inf("%s: %zd cryptographic algorithms found in /proc/crypto\n",
 			args->name, proc_count);
 		pr_inf("%s: %zd cryptographic algorithms in total (with defconfigs)\n",
 			args->name, count);
 		if (internal)
 			pr_inf("%s: %zd cryptographic algorithms are internal and may be unused\n",
 				args->name, internal);
-		pr_unlock();
+		pr_block_end();
 	}
 
 	for (;;) {

stress-cyclic.c

@@ -855,6 +855,7 @@ static int stress_cyclic(const stress_args_t *args)
 				99.99,
 			};
 
+			pr_block_begin();
 			pr_inf("%s: sched %s: %" PRIu64 " ns delay, %zd samples\n",
 				args->name,
 				policies[cyclic_policy].name,
@@ -883,7 +884,7 @@ static int stress_cyclic(const stress_args_t *args)
 			if (rt_stats->index < rt_stats->index_reqd)
 				pr_inf("%s: Note: --cyclic-samples needed to be %zd to capture all the data for this run\n",
 					args->name, rt_stats->index_reqd);
-			pr_unlock();
+			pr_block_end();
 		} else {
 			pr_inf("%s: %10s: no latency information available\n",
 				args->name,

stress-hash.c

@@ -706,7 +706,7 @@ static int HOT OPTIMIZE3 stress_hash(const stress_args_t *args)
 	} while (stress_continue(args));
 
 	if (args->instance == 0) {
-		pr_lock();
+		pr_block_begin();
 		pr_inf("%s: %12.12s %15s %10s\n",
 			args->name, "hash", "hashes/sec", "chi squared");
 		for (i = 1; i < SIZEOF_ARRAY(hash_methods); i++) {
@@ -720,7 +720,7 @@ static int HOT OPTIMIZE3 stress_hash(const stress_args_t *args)
 					args->name, hash_methods[i].name, rate, stats->chi_squared);
 			}
 		}
-		pr_unlock();
+		pr_block_end();
 	}
 
 	stress_set_proc_state(args->name, STRESS_STATE_DEINIT);

stress-ipsec-mb.c

@@ -888,7 +888,7 @@ static int stress_ipsec_mb(const stress_args_t *args)
 		}
 	} while (stress_continue(args));
 
-	pr_lock();
+	pr_block_begin();
 	for (i = 0, j = 0; i < SIZEOF_ARRAY(mb_features); i++) {
 		const ipsec_stats_t *stats = &mb_features[i].stats;
 
@@ -905,7 +905,7 @@ static int stress_ipsec_mb(const stress_args_t *args)
 			j++;
 		}
 	}
-	pr_unlock();
+	pr_block_end();
 
 	stress_set_proc_state(args->name, STRESS_STATE_DEINIT);
 

stress-memrate.c

@@ -1096,7 +1096,7 @@ static int stress_memrate(const stress_args_t *args)
 
 	stress_set_proc_state(args->name, STRESS_STATE_DEINIT);
 
-	pr_lock();
+	pr_block_begin();
 	for (i = 0; i < memrate_items; i++) {
 		if (!context.stats[i].valid)
 			continue;
@@ -1111,7 +1111,7 @@ static int stress_memrate(const stress_args_t *args)
 				args->name, memrate_info[i].name);
 		}
 	}
-	pr_unlock();
+	pr_block_end();
 
 	(void)munmap((void *)context.stats, stats_size);
 

stress-ng.c

@@ -1563,7 +1563,6 @@ static void MLOCKED_TEXT stress_run(
 				stress_set_proc_state(name, STRESS_STATE_EXIT);
 				if (terminate_signum)
 					rc = EXIT_SIGNALED;
-				pr_lock_exited(child_pid);
 				g_shared->instance_count.exited++;
 				g_shared->instance_count.started--;
 				if (rc == EXIT_FAILURE)
@@ -1831,7 +1830,7 @@ static void stress_metrics_dump(FILE *yaml)
 	stress_stressor_t *ss;
 	bool misc_metrics = false;
 
-	pr_lock();
+	pr_block_begin();
 	if (g_opt_flags & OPT_FLAGS_METRICS_BRIEF) {
 		pr_metrics("%-13s %9.9s %9.9s %9.9s %9.9s %12s %14s\n",
 			   "stressor", "bogo ops", "real time", "usr time",
@@ -2054,7 +2053,7 @@ static void stress_metrics_dump(FILE *yaml)
 			}
 		}
 	}
-	pr_unlock();
+	pr_block_end();
 }
 
 /*
@@ -3512,7 +3511,6 @@ int main(int argc, char **argv, char **envp)
 	/*
 	 *  And now shared memory is created, initialize pr_* lock mechanism
 	 */
-	pr_lock_init();
 	if (!stress_shared_heap_init()) {
 		pr_err("failed to create shared heap \n");
 		goto exit_shared_unmap;

stress-ng.h

@@ -599,15 +599,6 @@ typedef struct {
 		uint16_t padding1;	/* alignment padding */
 		uint32_t ways;		/* cache ways size */
 	} mem_cache;
-#if defined(HAVE_ATOMIC_COMPARE_EXCHANGE) &&	\
-    defined(HAVE_ATOMIC_STORE)
-	struct {
-		double whence;		/* pr_* lock time */
-		pid_t atomic_lock;	/* pr_* atomic spinlock */
-		int lock_count;		/* pr_* lock count, release when zero */
-		pid_t pid;		/* pid owning the lock */
-	} pr;
-#endif
 	struct {
 		uint32_t hash[STRESS_WARN_HASH_MAX]; /* hash patterns */
 		void *lock;		/* protection lock */

stress-pci.c

@@ -312,7 +312,7 @@ static int stress_pci(const stress_args_t *args)
 	stress_set_proc_state(args->name, STRESS_STATE_DEINIT);
 
 	if (args->instance == 0) {
-		pr_lock();
+		pr_block_begin();
 		pr_inf("%s: PCI space read rates in MB per sec for stressor instance 0:\n", args->name);
 		pr_inf("%s: PCI Device     Config Resource\n", args->name);
 		for (pci_info = pci_info_list; pci_info; pci_info = pci_info->next) {
@@ -321,7 +321,7 @@ static int stress_pci(const stress_args_t *args)
 				stress_pci_rate(&pci_info->metrics[PCI_METRICS_CONFIG]) / MB,
 				stress_pci_rate(&pci_info->metrics[PCI_METRICS_RESOURCE]) / MB);
 		}
-		pr_unlock();
+		pr_block_end();
 	}
 
 	stress_pci_info_free(pci_info_list);

stress-pty.c

@@ -413,7 +413,7 @@ static int stress_pty(const stress_args_t *args)
 			int ldisc, orig_ldisc;
 
 			if (ioctl(ptys[i].follower, TIOCGETD, &orig_ldisc) == 0) {
-				pr_lock();
+				pr_block_begin();
 				for (ldisc = 0; ldisc < max_ldisc; ldisc++) {
 					int j;
 
@@ -428,7 +428,7 @@ static int stress_pty(const stress_args_t *args)
 					}
 				}
 				VOID_RET(int, ioctl(ptys[i].follower, TIOCSETD, &orig_ldisc));
-				pr_unlock();
+				pr_block_end();
 				shim_sched_yield();
 			}
 		}

stress-resched.c

@@ -231,7 +231,7 @@ static int stress_resched(const stress_args_t *args)
 		for (i = 0; i < pids_max; i++)
 			total_yields += yields[i];
 
-		pr_lock();
+		pr_block_begin();
 		for (i = 0; i < pids_max; i++) {
 			if (yields[i] > 0) {
 				double percent = 100.0 * ((double)yields[i] / (double)total_yields);
@@ -248,7 +248,7 @@ static int stress_resched(const stress_args_t *args)
 				}
 			}
 		}
-		pr_unlock();
+		pr_block_end();
 	}
 
 	if (yields != NULL)

stress-syscall.c

@@ -8435,7 +8435,7 @@ static void stress_syscall_report_syscall_top10(const stress_args_t *args)
 	}
 	syscall_shellsort_size_t(sort_index, STRESS_SYSCALLS_MAX, cmp_syscall_time);
 
-	pr_lock();
+	pr_block_begin();
 	pr_inf("%s: Top 10 fastest system calls (timings in nanosecs):\n", args->name);
 	pr_inf("%s: %25s %10s %10s\n", args->name, "System Call", "Avg (ns)", "Min (ns)");
 	for (n = 0, i = 0; (i < STRESS_SYSCALLS_MAX) && (n < max); i++) {
@@ -8451,7 +8451,7 @@ static void stress_syscall_report_syscall_top10(const stress_args_t *args)
 			n++;
 		}
 	}
-	pr_unlock();
+	pr_block_end();
 }
 
 static int cmp_test_duration(const void *p1, const void *p2)

stress-sysinval.c

@@ -2820,15 +2820,15 @@ static int stress_sysinval(const stress_args_t *args)
 		if (current_context->crash_count[i] > 0)
 			syscalls_crashed += current_context->crash_count[i];
 	}
-	pr_lock();
+	pr_block_begin();
 	pr_dbg("%s: %" PRIu64 " of %" PRIu64 " (%.2f%%) unique system calls exercised\n",
 		args->name, syscalls_exercised, syscalls_unique,
 		100.0 * ((double)syscalls_exercised) / (double)syscalls_unique);
 	pr_dbg("%s: %" PRIu64 " unique syscalls argument combinations causing premature child termination\n",
 		args->name, syscalls_crashed);
 	pr_dbg("%s: ignored %" PRIu64 " unique syscall patterns that were not failing and %" PRIu64 " that timed out\n",
 		args->name, current_context->skip_errno_zero, current_context->skip_timed_out);
-	pr_unlock();
+	pr_block_end();
 
 	stress_bogo_set(args, current_context->counter);
 

stress-vecshuf.c

@@ -389,7 +389,7 @@ static int stress_vecshuf(const stress_args_t *args)
 		double total_ops = 0.0;
 		double total_bytes = 0.0;
 
-		pr_lock();
+		pr_block_begin();
 		pr_dbg("%s: shuffle throughput for just stressor instance 0:\n", args->name);
 		pr_dbg("%s: %14.14s %13.13s %13.13s %13.13s\n",
 			args->name, "Method", "MB/sec", "Mshuffles/sec", "% exec time");
@@ -424,7 +424,7 @@ static int stress_vecshuf(const stress_args_t *args)
 			pr_dbg("%s: %14.14s %13.3f %13.3f\n", args->name,
 				"Mean:", bytes_rate, ops_rate);
 		}
-		pr_unlock();
+		pr_block_end();
 	}
 
 	stress_set_proc_state(args->name, STRESS_STATE_DEINIT);

stress-vecwide.c

@@ -222,7 +222,7 @@ static int stress_vecwide(const stress_args_t *args)
 	}
 
 	if (args->instance == 0) {
-		pr_lock();
+		pr_block_begin();
 		pr_dbg("%s: Bits  %% Dur  %% Exp (x Win) (> 1.0 is better than expected)\n", args->name);
 		for (i = 0; i < SIZEOF_ARRAY(stress_vecwide_funcs); i++) {
 			double dur_pc, exp_pc, win;
@@ -237,7 +237,7 @@ static int stress_vecwide(const stress_args_t *args)
 		}
 		pr_dbg("%s: Key: Bits = vector width in bits, Dur = %% total run time,\n", args->name);
 		pr_dbg("%s       Exp = %% expected run time, Win = performance gain\n", args->name);
-		pr_unlock();
+		pr_block_end();
 	}
 
 	for (i = 0; i < SIZEOF_ARRAY(stress_vecwide_funcs); i++) {