mcap/src/test/logger_tests.jai

// The logger's pieces on their own: the MPSC queue under contention, the Event Log ring's
// capacity changes, and the event_log_capacity setting's parsing.

#scope_file

checks_run    := 0;
checks_failed := 0;

MAX_GROUPS :: 8;
group_names  : [MAX_GROUPS] string;
group_checks : [MAX_GROUPS] int;
group_fails  : [MAX_GROUPS] int;
group_count  := 0;

output_builder: *String_Builder;

emit :: (format_string: string, args: ..Any) {
  if output_builder  print_to_builder(output_builder, format_string, ..args);
  else               print(format_string, ..args);
} @PrintLike

group :: (name: string) {
  assert(group_count < MAX_GROUPS, "raise MAX_GROUPS");
  group_names[group_count] = name;
  group_count += 1;
  emit("\n-- % --\n", name);
}

expect :: (condition: bool, format: string, args: ..Any, loc := #caller_location) {
  checks_run += 1;
  if group_count  group_checks[group_count-1] += 1;
  if condition return;

  checks_failed += 1;
  if group_count  group_fails[group_count-1] += 1;
  emit("  FAIL  [%:%]  %\n", group_names[max(group_count-1, 0)], loc.line_number, tprint(format, ..args));
}

report :: () -> bool {
  emit("\n");
  for 0..group_count-1 {
    if group_fails[it]  emit("  % -- % checks, % FAILED\n", group_names[it], group_checks[it], group_fails[it]);
    else                emit("  % -- % checks\n", group_names[it], group_checks[it]);
  }
  if checks_failed  emit("\n% OF % LOGGER CHECKS FAILED\n", checks_failed, checks_run);
  else              emit("\nALL LOGGER TESTS PASSED  (% checks over % groups)\n", checks_run, group_count);
  return checks_failed == 0;
}

//
// The queue: producers push numbered nodes while this thread pops; every node must arrive once,
// and each producer's in the order it pushed them.
//

MPSC_PRODUCERS          :: 8;
MPSC_NODES_PER_PRODUCER :: 50_000;
MPSC_TIMEOUT_MS         :: 30_000;

Test_Node :: struct {
  using link: Mpsc_Node;
  producer: s64;
  sequence: s64;
}

Producer :: struct {
  queue: *Mpsc_Queue;
  nodes: [] Test_Node;
}

producer_proc :: (thread: *Thread) -> s64 {
  producer := cast(*Producer) thread.data;
  for * producer.nodes  mpsc_push(producer.queue, *it.link);
  return 0;
}

mpsc_tests :: () {
  group("mpsc queue");

  queue := New(Mpsc_Queue);
  defer free(queue);
  mpsc_init(queue);

  expect(mpsc_pop(queue) == null, "a new queue popped a node");

  producers: [MPSC_PRODUCERS] Producer;
  threads:   [MPSC_PRODUCERS] Thread;
  started:   [MPSC_PRODUCERS] bool;
  for * producers {
    it.queue = queue;
    it.nodes = NewArray(MPSC_NODES_PER_PRODUCER, Test_Node);
    for * node, sequence: it.nodes {
      node.producer = it_index;
      node.sequence = sequence;
    }
  }
  defer for producers  array_free(it.nodes);

  for * threads {
    started[it_index] = thread_init(it, producer_proc, name = tprint("mpsc test %", it_index + 1));
    expect(started[it_index], "could not start producer %", it_index);
    if !started[it_index]  continue;
    it.data = *producers[it_index];
    thread_start(it);
  }

  expected_total := 0;
  for started  if it  expected_total += MPSC_NODES_PER_PRODUCER;

  next_sequence: [MPSC_PRODUCERS] s64;
  received := 0;
  out_of_order := 0;
  start := current_time_monotonic();
  while received < expected_total {
    node := cast(*Test_Node) mpsc_pop(queue);
    if !node {
      if to_milliseconds(current_time_monotonic() - start) > MPSC_TIMEOUT_MS  break;
      continue;
    }
    if node.sequence != next_sequence[node.producer]  out_of_order += 1;
    next_sequence[node.producer] = node.sequence + 1;
    received += 1;
  }

  for * threads {
    if !started[it_index]  continue;
    thread_is_done(it, -1);
    thread_deinit(it);
  }

  expect(received == expected_total, "received % of % nodes", received, expected_total);
  expect(out_of_order == 0, "% nodes arrived out of their producer's order", out_of_order);
  for next_sequence  expect(!started[it_index] || it == MPSC_NODES_PER_PRODUCER, "producer % delivered % of %", it_index, it, MPSC_NODES_PER_PRODUCER);
  expect(mpsc_pop(queue) == null, "the drained queue popped another node");

  // After a drain the queue is reusable.
  extra: Test_Node;
  mpsc_push(queue, *extra.link);
  expect(cast(*Test_Node) mpsc_pop(queue) == *extra, "a push after the drain did not pop back");
  expect(mpsc_pop(queue) == null, "the queue was not empty after the last pop");
}

//
// The Event Log ring.
//

new_entry :: (sequence: s64) -> *Log_Message {
  entry := cast(*Log_Message) alloc(size_of(Log_Message),, context.default_allocator);
  memset(entry, 0, size_of(Log_Message));
  entry.thread_index = sequence;   // stands in for the line's identity here
  return entry;
}

// The entries' sequence numbers, oldest first, as one string.
ring_contents :: (ring: *Circle_Buffer(*Log_Message)) -> string {
  builder: String_Builder;
  builder.allocator = temp;
  for 0..count(ring.*)-1 {
    if it  append(*builder, " ");
    print_to_builder(*builder, "%", ring.*[it].thread_index);
  }
  return builder_to_string(*builder,, temp);
}

ring_tests :: () {
  group("event log ring");

  ring: Circle_Buffer(*Log_Message);
  ring.allocator = context.default_allocator;
  defer {
    for ring  free(it,, context.default_allocator);
    delete(*ring);
  }

  freed := event_log_resize(*ring, 4);
  expect(freed == 0 && ring.allocated == 4, "sizing an empty ring freed % and allocated %", freed, ring.allocated);

  dropped := 0;
  for 1..6  if event_log_insert(*ring, new_entry(it))  dropped += 1;
  expect(dropped == 2, "filling 4 slots with 6 dropped %", dropped);
  expect(ring_contents(*ring) == "3 4 5 6", "after 6 inserts the ring held %", ring_contents(*ring));

  freed = event_log_resize(*ring, 2);
  expect(freed == 2, "shrinking 4 to 2 freed %", freed);
  expect(ring_contents(*ring) == "5 6", "after shrinking the ring held %", ring_contents(*ring));

  freed = event_log_resize(*ring, 5);
  expect(freed == 0, "growing freed %", freed);
  expect(ring_contents(*ring) == "5 6", "after growing the ring held %", ring_contents(*ring));

  for 7..9  if event_log_insert(*ring, new_entry(it))  dropped += 1;
  expect(dropped == 2, "inserts into free slots dropped more, % in all", dropped);
  expect(ring_contents(*ring) == "5 6 7 8 9", "after refilling the ring held %", ring_contents(*ring));

  event_log_insert(*ring, new_entry(10));
  expect(ring_contents(*ring) == "6 7 8 9 10", "past capacity again the ring held %", ring_contents(*ring));
}

//
// The setting.
//

settings_tests :: () {
  group("event_log_capacity setting");

  Case :: struct { value: string; seen: bool; capacity: s64; }
  CASES :: Case.[
    .{"100",       true,  100},
    .{"  250  ",   true,  250},
    .{"5",         true,  EVENT_LOG_CAPACITY_MIN},
    .{"2000000",   true,  EVENT_LOG_CAPACITY_MAX},
    .{"abc",       false, EVENT_LOG_CAPACITY_DEFAULT},
    .{"12abc",     false, EVENT_LOG_CAPACITY_DEFAULT},
    .{"",          false, EVENT_LOG_CAPACITY_DEFAULT},
  ];

  for CASES {
    data := tprint("@version %\n[logging]\nevent_log_capacity: %\n", APP_USER_SETTINGS_VERSION, it.value);
    settings: App_User_Settings;
    ok, seen := settings_parse("logger_tests", data, *settings);
    defer settings_free(*settings);
    expect(ok, "the settings with % did not parse", it.value);
    expect(seen.event_log == it.seen, "'%' was seen: %", it.value, seen.event_log);
    expect(settings.event_log_capacity == it.capacity, "'%' gave capacity %, not %", it.value, settings.event_log_capacity, it.capacity);
  }

  data := tprint("@version %\n[window]\nwidth_fraction: 0.5\n", APP_USER_SETTINGS_VERSION);
  settings: App_User_Settings;
  ok, seen := settings_parse("logger_tests", data, *settings);
  defer settings_free(*settings);
  expect(ok && !seen.event_log && settings.event_log_capacity == EVENT_LOG_CAPACITY_DEFAULT,
         "a file without the key gave seen % and capacity %", seen.event_log, settings.event_log_capacity);
}

#scope_export

run_logger_tests :: (builder: *String_Builder = null) -> bool {
  output_builder = builder;
  emit("=== logger test suite ===\n");
  emit("  (expecting logged errors from the malformed settings)\n");

  push_allocator(context.default_allocator);
  mpsc_tests();
  ring_tests();
  settings_tests();
  return report();
}