zircon/kernel/lib/jtrace/jtrace_internal.h - fuchsia - Git at Google

 // Copyright 2021 The Fuchsia Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.

 #ifndef ZIRCON_KERNEL_LIB_JTRACE_JTRACE_INTERNAL_H_
 #define ZIRCON_KERNEL_LIB_JTRACE_JTRACE_INTERNAL_H_

 #include <lib/affine/ratio.h>
 #include <lib/arch/intrin.h>
 #include <lib/fit/defer.h>
 #include <lib/jtrace/jtrace.h>
 #include <platform.h>
 #include <zircon/time.h>

 #include <arch/ops.h>
 #include <fbl/canary.h>
 #include <kernel/auto_preempt_disabler.h>
 #include <kernel/cpu.h>
 #include <ktl/algorithm.h>
 #include <ktl/atomic.h>
 #include <ktl/limits.h>
 #include <ktl/optional.h>
 #include <ktl/span.h>
 #include <pretty/hexdump.h>
 #include <vm/vm.h>
 #include <vm/vm_aspace.h>

 namespace jtrace {

 static constexpr zx_koid_t kUnknownTid = ktl::numeric_limits<zx_koid_t>::max();

 // fwd decl of our tests structure.  This allows the JTrace class to be friends with the tests.
 struct tests;

 // A small utility function, used only locally.
 // TODO(johngro): Add this to ktl?
 template <typename T, typename U>
 static inline constexpr T saturate(U val) {
   return (val > ktl::numeric_limits<T>::max())   ? ktl::numeric_limits<T>::max()
          : (val < ktl::numeric_limits<T>::min()) ? ktl::numeric_limits<T>::min()
                                                  : static_cast<T>(val);
 }

 // The definition of an interface used to abstract printing operations used when
 // dumping trace buffers. This implementation is replaced during testing in
 // order to verify that trace dumps are working as expected.
 class TraceHooks {
  public:
   TraceHooks() = default;
   virtual ~TraceHooks() = default;

   virtual void PrintWarning(const char* fmt, ...) __PRINTFLIKE(2, 3) = 0;
   virtual void PrintInfo(const char* fmt, ...) __PRINTFLIKE(2, 3) = 0;
   virtual void Hexdump(const void* data, size_t size) = 0;
   virtual void PerCpuDumpStarted() {}
   virtual void PrintTraceEntry(const Entry<UseLargeEntries::Yes>& e, TraceBufferType buf_type,
                                zx_time_t ts, zx_duration_t delta = 0) = 0;
   virtual void PrintTraceEntry(const Entry<UseLargeEntries::No>& e, TraceBufferType buf_type,
                                zx_time_t ts, zx_duration_t delta = 0) = 0;
 };

 // A traits struct which holds the configuration of an instance of the debug trace subsystem.
 template <size_t _kTargetBufferSize, size_t _kLastEntryStorage,
           ::jtrace::IsPersistent _kIsPersistent, ::jtrace::UseLargeEntries _kUseLargeEntries,
           ::jtrace::UseMonoTimestamps _kUseMonoTimestamps>
 struct Config {
   static constexpr size_t kTargetBufferSize = _kTargetBufferSize;
   static constexpr size_t kLastEntryStorage = _kLastEntryStorage;
   static constexpr ::jtrace::IsPersistent kIsPersistent = _kIsPersistent;
   static constexpr ::jtrace::UseLargeEntries kUseLargeEntries = _kUseLargeEntries;
   static constexpr ::jtrace::UseMonoTimestamps kUseMonoTimestamps = _kUseMonoTimestamps;
   using Entry = ::jtrace::Entry<kUseLargeEntries>;
 };

 template <typename Config>
 struct Header {
   using Entry = typename Config::Entry;

   static constexpr uint32_t kNoMagic = 0;
   static constexpr uint32_t kMagic = fbl::magic("Jtrc");

   uint32_t magic{kMagic};
   ktl::atomic<uint32_t> wr{0};
   Entry last_cpu_entries_[Config::kLastEntryStorage];
   Entry entries[];
 };

 template <typename Config>
 class JTrace {
  public:
   using Entry = typename Config::Entry;
   using Header = ::jtrace::Header<Config>;

   static inline constexpr size_t kRequiredBufferAlignment = alignof(Header);

   JTrace(TraceHooks& hooks) : hooks_(hooks) {}

   // No copy, no move.
   JTrace(const JTrace&) = delete;
   JTrace& operator=(const JTrace&) = delete;
   JTrace(JTrace&&) = delete;
   JTrace& operator=(JTrace&&) = delete;

   void SetAfterThreadInitEarly() { after_thread_init_early_ = true; }

   void SetLocation(ktl::span<uint8_t> storage) {
     // The location of the trace buffer should only ever get set once, either
     // during the init call for a non-persistent log, or later on during the
     // allocation of persistent RAM during ZBI processing.  If an attempt is
     // made to set the location twice, simply ignore it.  Do not attempt to
     // debug assert, as we are very likely to be so early in boot that it would
     // be very difficult to debug such an assert.
     if ((storage_.data() != nullptr) || !storage_.empty()) {
       return;
     }

     // Reject the buffer if it is null/empty for any reason, or if the pointer
     // provided does not meet the alignment requirements of our header.
     if ((storage.data() == nullptr) || storage.empty() ||
         (reinterpret_cast<uintptr_t>(storage.data()) % alignof(decltype(*hdr())))) {
       return;
     }

     // If the supplied storage is not enough to hold the header and even a
     // single trace entry, then just disable debug tracing by setting the header
     // location and the number of entries to nothing.  In theory, these should
     // already be nullptr and 0, but we explicitly set them anyway since (again)
     // ASSERTing is not really an option given how early on in boot we are
     // likely to be right now.
     if (storage.size() < sizeof(Header) + sizeof(Entry)) {
       return;
     }

     // If this is a persistent trace and we have a recovery buffer, attempt to
     // recover the log from our storage before proceeding to re-init our trace
     // storage.
     storage_ = storage;
     if constexpr (kRecoveryBufferSize > 0) {
       ::memcpy(recovered_buf_, storage_.data(), ktl::min(sizeof(recovered_buf_), storage_.size()));
     }

     // Go ahead and initialize our header and the number of entries we can hold
     // in our log, then flush this out to physical RAM if this is a persistent
     // trace buffer.
     new (storage_.data()) Header();
     entry_cnt_ = static_cast<uint32_t>((saturate<uint32_t>(storage_.size()) - sizeof(Header)) /
                                        sizeof(Entry));
     CleanCache(storage_.data(), storage_.size());
   }

   ktl::span<uint8_t> GetLocation() const { return storage_; }

   void Invalidate() {
     if (hdr() != nullptr) {
       hdr()->magic = Header::kNoMagic;
       CleanCache(hdr(), sizeof(*hdr()));
     }
   }

   void Log(Entry& entry) {
     if (hdr() == nullptr) {
       return;
     }

     // Record the fact that there is now a trace operation in progress, making
     // sure that we remember to decrement this count when we exit this method.
     trace_ops_in_flight_.fetch_add(1, ktl::memory_order_acq_rel);
     auto cleanup =
         fit::defer([this]() { trace_ops_in_flight_.fetch_add(-1, ktl::memory_order_acq_rel); });

     // Try to reserve a slot to write a record into.  This should only fail if
     // the tracing is temporarily disabled for dumping.
     ktl::optional<uint32_t> opt_wr = ReserveSlot();
     if (!opt_wr.has_value()) {
       return;
     }

     // Go ahead and finish filling out the entry, then copy the entry into the
     // main trace buffer, and (if enabled) into the per-cpu last entry slot in
     // the header.  Please note 2 potentially subtle points about this:
     //
     // 1) We mutate the log entry passed to us by the caller to finish filling
     //    it out, then record that entry in both places.  It is important that
     //    we don't copy the record into the main trace buffer and _then_ finish
     //    filling out the record (copying it from the main trace buffer to the
     //    per-cpu header slot afterwards).  There is a small chance that between
     //    these operations, the log ends up wrapping and our currently assigned
     //    slot gets stomped (causing the per-cpu record to be corrupted).
     // 2) We need to disable preemption for the time period between when we
     //    record the CPU ID in the trace entry, and when write that entry into
     //    the per-cpu slot.  Failure to do this could result in us recording CPU
     //    X in the entry, but then being moved to CPU Y before writing to the
     //    per-cpu slot for X (and setting up a potential race between us and
     //    whoever is running on CPU X now).  Note that we cannot disable
     //    preemption until after thread_init_early has been called, but at that
     //    point in boot, interrupts are disabled and the secondary CPUs are not
     //    running yet, so that should be OK.  Also, we don't want to disable and
     //    later attempt to re-enable preemption if interrupts are currently off
     //    (as they would be when a spinlock is held) as it _could_ trip an
     //    assert in the consistency checks for the preempt-disabler.  If
     //    interrupts are already disabled, we should be fine.  We can't change
     //    CPUs at that point in time anyway.
     //
     const uint32_t wr = opt_wr.value();
     {
       const bool disable_preemption = after_thread_init_early_ && !arch_ints_disabled();
       if (disable_preemption) {
         Thread::Current::preemption_state().PreemptDisable();
       }

       if constexpr (Config::kUseMonoTimestamps == UseMonoTimestamps::Yes) {
         entry.ts_ticks = current_mono_ticks();
       } else {
         entry.ts_ticks = current_boot_ticks();
       }
       if (entry.ts_ticks == 0) {
         entry.ts_ticks = kZeroReplacement;
       }

       entry.cpu_id = arch_curr_cpu_num();
       if constexpr (Config::kUseLargeEntries == UseLargeEntries::Yes) {
         entry.tid = after_thread_init_early_ ? Thread::Current::Get()->tid() : kUnknownTid;
       }

       hdr()->entries[wr] = entry;

       if constexpr (Config::kLastEntryStorage > 0) {
         if (entry.cpu_id < ktl::size(hdr()->last_cpu_entries_)) {
           hdr()->last_cpu_entries_[entry.cpu_id] = entry;
         }
       }

       if (disable_preemption) {
         Thread::Current::preemption_state().PreemptReenable();
       }
     }

     // Flush the header and the entry if this is a persistent trace.
     CleanCache(hdr(), sizeof(*hdr()));
     CleanCache(hdr()->entries + wr, sizeof(Entry));
   }

   // |timeout| controls how long this method will wait (spin) for other threads
   // to complete in progress writes before continuing on and dumping the buffer.
   void Dump(zx_duration_boot_t timeout) {
     if (hdr() == nullptr) {
       hooks_.PrintWarning("No debug trace buffer was ever configured\n");
       return;
     }

     // Disable tracing and give any thread currently in the process of writing a
     // record some time to get out of the way.  Note that this is a best effort
     // approach to disabling the tracing during our dump.  It is important that
     // debug tracing remain lockless at all times.  The worst case scenario here
     // is that we end up with a partially garbled trace record.
     SetTraceEnabled(false);

     const affine::Ratio ticks_to_time_ratio = timer_get_ticks_to_time_ratio();
     const zx_instant_boot_ticks_t deadline =
         zx_ticks_add_ticks(current_boot_ticks(), ticks_to_time_ratio.Inverse().Scale(timeout));
     while ((trace_ops_in_flight_.load(ktl::memory_order_acquire) > 0) &&
            (current_boot_ticks() < deadline)) {
       // just spin while we wait.
       arch::Yield();
     }

     // Print a warning if we never saw the in flight op-count hit zero, then go
     // ahead and dump the current buffer.
     if (current_boot_ticks() >= deadline) {
       hooks_.PrintWarning(
           "Warning: ops in flight was never observed at zero while waiting to dump the current "
           "trace buffer.  Some trace records might be corrupt.\n");
     }

     ktl::span<const uint8_t> data{reinterpret_cast<const uint8_t*>(hdr()),
                                   sizeof(*hdr()) + (sizeof(Entry) * entry_cnt_)};
     Dump(data, TraceBufferType::Current);

     // Finally, go ahead and re-enable tracing.
     SetTraceEnabled(true);
   }

   void DumpRecovered() {
     if constexpr (kRecoveryBufferSize > 0) {
       Dump({recovered_buf_, sizeof(recovered_buf_)}, TraceBufferType::Recovered);
     } else {
       hooks_.PrintWarning(
           "Debug tracing is not configured for persistent tracing.  There is no recovered buffer "
           "to dump.\n");
     }
   }

  private:
   // Tests are allowed to peek at our private state.
   friend struct ::jtrace::tests;

   static constexpr uint32_t kTraceDisabledFlag = 0x80000000;
   static constexpr uint32_t kRecoveryBufferSize =
       (Config::kIsPersistent == jtrace::IsPersistent::Yes) ? Config::kTargetBufferSize : 0;

   static inline void CleanCache(void* ptr, size_t len) {
     // Trace data only needs to be flushed to physical RAM if the trace is meant
     // to be persistent.
     if constexpr (Config::kIsPersistent == jtrace::IsPersistent::Yes) {
       arch_clean_cache_range(reinterpret_cast<vaddr_t>(ptr), len);
     }
   }

   inline Header* hdr() { return reinterpret_cast<Header*>(storage_.data()); }

   ktl::optional<uint32_t> ReserveSlot() {
     uint32_t wr, next_wr;
     do {
       wr = hdr()->wr.load(ktl::memory_order_acquire);

       if (wr & kTraceDisabledFlag) {
         return ktl::nullopt;
       }

       next_wr = (wr + 1) % entry_cnt_;
     } while (!hdr()->wr.compare_exchange_weak(wr, next_wr, ktl::memory_order_acq_rel));

     return wr;
   }

   void SetTraceEnabled(bool enabled) {
     uint32_t wr, next_wr;
     do {
       wr = hdr()->wr.load(ktl::memory_order_acquire);
       next_wr = enabled ? (wr & ~kTraceDisabledFlag) : (wr | kTraceDisabledFlag);
     } while (!hdr()->wr.compare_exchange_weak(wr, next_wr));
   }

   void Dump(ktl::span<const uint8_t> buf, TraceBufferType buf_type) {
     auto dump_corrupted_log = fit::defer([this, buf]() {
       hooks_.PrintWarning("JTRACE: Dumping corrupted log\n");
       hooks_.Hexdump(buf.data(), buf.size());
     });

     const size_t total_size = (sizeof(*hdr()) + (entry_cnt_ * sizeof(Entry)));
     if (total_size > buf.size()) {
       hooks_.PrintWarning("JTRACE: recovery buffer too small (%zu) to hold %u entries\n",
                           buf.size(), entry_cnt_);
       return;
     }

     const Header* hdr = reinterpret_cast<const Header*>(buf.data());
     const Entry* entries = hdr->entries;
     if (hdr->magic == Header::kNoMagic) {
       hooks_.PrintInfo("JTRACE: Log appears clean, not dumping it (recoverd %p main %p len %zu)\n",
                        buf.data(), this->hdr(), total_size);
       dump_corrupted_log.cancel();
       return;
     }

     const uint32_t wr = hdr->wr.load() & ~kTraceDisabledFlag;
     if ((hdr->magic != Header::kMagic) || (wr >= entry_cnt_)) {
       hooks_.PrintWarning("JTRACE: Bad header: Magic 0x%08x Wr %u Entries %u\n", hdr->magic,
                           hdr->wr.load(), entry_cnt_);
       return;
     }

     dump_corrupted_log.cancel();

     // Figure out how many entries we will dump, and where to start dumping
     // from.  We skip any initial entries which have a timestamp of zero.  We
     // never deliberately write a timestamps of zero, meaning that the entries
     // are skipping were never written, because the trace never wrapped.
     uint32_t rd = wr;
     uint32_t todo = entry_cnt_;
     while (todo) {
       const auto& e = entries[rd];
       if (e.ts_ticks != 0) {
         break;
       }
       rd = (rd + 1) % entry_cnt_;
       --todo;
     }

     auto ConvertTimestamp = [](const Entry& e) -> zx_time_t {
       const affine::Ratio ticks_to_time_ratio = timer_get_ticks_to_time_ratio();
       const zx_ticks_t ts = (e.ts_ticks == kZeroReplacement) ? 0 : e.ts_ticks;
       return ticks_to_time_ratio.Scale(ts);
     };

     if (todo) {
       hooks_.PrintInfo("JTRACE: Recovered %u/%u entries\n", todo, entry_cnt_);
       zx_time_t prev_ts = ConvertTimestamp(entries[rd]);

       for (; todo != 0; --todo) {
         const auto& e = entries[rd];
         const zx_time_t ts = ConvertTimestamp(entries[rd]);

         hooks_.PrintTraceEntry(e, buf_type, ts, ts - prev_ts);
         prev_ts = ts;
         rd = (rd + 1) % entry_cnt_;
       }

       // If we are configured to track per-cpu last events, go ahead and print
       // them out.
       if constexpr (Config::kLastEntryStorage > 0) {
         hooks_.PerCpuDumpStarted();
         hooks_.PrintInfo("\n");
         hooks_.PrintInfo("JTRACE: Last recorded per-CPU events.\n");

         if (Config::kLastEntryStorage != arch_max_num_cpus()) {
           hooks_.PrintWarning(
               "JTRACE: Warning! Configured per-cpu last entry count (%zu) does not match target's "
               "number of CPUs (%u)\n",
               Config::kLastEntryStorage, arch_max_num_cpus());
         }

         for (const Entry& e : hdr->last_cpu_entries_) {
           zx_time_t ts = ConvertTimestamp(e);
           hooks_.PrintTraceEntry(e, buf_type, ts);
         }
       }

       const int64_t last_sec = prev_ts / ZX_SEC(1);
       const int64_t last_nsec = prev_ts % ZX_SEC(1);
       hooks_.PrintInfo("\n");
       hooks_.PrintInfo("JTRACE: Last log timestamp [%4ld.%09ld]\n", last_sec, last_nsec);
     } else {
       hooks_.PrintInfo("JTRACE: no entries\n");
     }
   }

   // We never want to deliberately log a timestamp of zero.  The buffer is
   // filled with zeros at the start, and we skip entries with zero time stamps
   // when trying to find the read pointer during a dump operation.
   // Unfortunately, if JTRACE entries are being created before the clock has
   // been selected, the time they are going to get is always 0.  So, instead, we
   // replace that value with this constant instead, and substitute back again
   // during the dump.
   static inline constexpr zx_ticks_t kZeroReplacement = ktl::numeric_limits<zx_ticks_t>::min();

   TraceHooks& hooks_;
   ktl::span<uint8_t> storage_{};
   uint32_t entry_cnt_{0};
   ktl::atomic<uint32_t> trace_ops_in_flight_{0};
   bool after_thread_init_early_ = false;
   alignas(Header) uint8_t recovered_buf_[kRecoveryBufferSize];
 };

 }  // namespace jtrace

 #endif  // ZIRCON_KERNEL_LIB_JTRACE_JTRACE_INTERNAL_H_
	// Copyright 2021 The Fuchsia Authors. All rights reserved.
	// Use of this source code is governed by a BSD-style license that can be
	// found in the LICENSE file.

	#ifndef ZIRCON_KERNEL_LIB_JTRACE_JTRACE_INTERNAL_H_
	#define ZIRCON_KERNEL_LIB_JTRACE_JTRACE_INTERNAL_H_

	#include <lib/affine/ratio.h>
	#include <lib/arch/intrin.h>
	#include <lib/fit/defer.h>
	#include <lib/jtrace/jtrace.h>
	#include <platform.h>
	#include <zircon/time.h>

	#include <arch/ops.h>
	#include <fbl/canary.h>
	#include <kernel/auto_preempt_disabler.h>
	#include <kernel/cpu.h>
	#include <ktl/algorithm.h>
	#include <ktl/atomic.h>
	#include <ktl/limits.h>
	#include <ktl/optional.h>
	#include <ktl/span.h>
	#include <pretty/hexdump.h>
	#include <vm/vm.h>
	#include <vm/vm_aspace.h>

	namespace jtrace {

	static constexpr zx_koid_t kUnknownTid = ktl::numeric_limits<zx_koid_t>::max();

	// fwd decl of our tests structure. This allows the JTrace class to be friends with the tests.
	struct tests;

	// A small utility function, used only locally.
	// TODO(johngro): Add this to ktl?
	template <typename T, typename U>
	static inline constexpr T saturate(U val) {
	return (val > ktl::numeric_limits<T>::max()) ? ktl::numeric_limits<T>::max()
	: (val < ktl::numeric_limits<T>::min()) ? ktl::numeric_limits<T>::min()
	: static_cast<T>(val);
	}

	// The definition of an interface used to abstract printing operations used when
	// dumping trace buffers. This implementation is replaced during testing in
	// order to verify that trace dumps are working as expected.
	class TraceHooks {
	public:
	TraceHooks() = default;
	virtual ~TraceHooks() = default;

	virtual void PrintWarning(const char* fmt, ...) __PRINTFLIKE(2, 3) = 0;
	virtual void PrintInfo(const char* fmt, ...) __PRINTFLIKE(2, 3) = 0;
	virtual void Hexdump(const void* data, size_t size) = 0;
	virtual void PerCpuDumpStarted() {}
	virtual void PrintTraceEntry(const Entry<UseLargeEntries::Yes>& e, TraceBufferType buf_type,
	zx_time_t ts, zx_duration_t delta = 0) = 0;
	virtual void PrintTraceEntry(const Entry<UseLargeEntries::No>& e, TraceBufferType buf_type,
	zx_time_t ts, zx_duration_t delta = 0) = 0;
	};

	// A traits struct which holds the configuration of an instance of the debug trace subsystem.
	template <size_t _kTargetBufferSize, size_t _kLastEntryStorage,
	::jtrace::IsPersistent _kIsPersistent, ::jtrace::UseLargeEntries _kUseLargeEntries,
	::jtrace::UseMonoTimestamps _kUseMonoTimestamps>
	struct Config {
	static constexpr size_t kTargetBufferSize = _kTargetBufferSize;
	static constexpr size_t kLastEntryStorage = _kLastEntryStorage;
	static constexpr ::jtrace::IsPersistent kIsPersistent = _kIsPersistent;
	static constexpr ::jtrace::UseLargeEntries kUseLargeEntries = _kUseLargeEntries;
	static constexpr ::jtrace::UseMonoTimestamps kUseMonoTimestamps = _kUseMonoTimestamps;
	using Entry = ::jtrace::Entry<kUseLargeEntries>;
	};

	template <typename Config>
	struct Header {
	using Entry = typename Config::Entry;

	static constexpr uint32_t kNoMagic = 0;
	static constexpr uint32_t kMagic = fbl::magic("Jtrc");

	uint32_t magic{kMagic};
	ktl::atomic<uint32_t> wr{0};
	Entry last_cpu_entries_[Config::kLastEntryStorage];
	Entry entries[];
	};

	template <typename Config>
	class JTrace {
	public:
	using Entry = typename Config::Entry;
	using Header = ::jtrace::Header<Config>;

	static inline constexpr size_t kRequiredBufferAlignment = alignof(Header);

	JTrace(TraceHooks& hooks) : hooks_(hooks) {}

	// No copy, no move.
	JTrace(const JTrace&) = delete;
	JTrace& operator=(const JTrace&) = delete;
	JTrace(JTrace&&) = delete;
	JTrace& operator=(JTrace&&) = delete;

	void SetAfterThreadInitEarly() { after_thread_init_early_ = true; }

	void SetLocation(ktl::span<uint8_t> storage) {
	// The location of the trace buffer should only ever get set once, either
	// during the init call for a non-persistent log, or later on during the
	// allocation of persistent RAM during ZBI processing. If an attempt is
	// made to set the location twice, simply ignore it. Do not attempt to
	// debug assert, as we are very likely to be so early in boot that it would
	// be very difficult to debug such an assert.
	if ((storage_.data() != nullptr) \|\| !storage_.empty()) {
	return;
	}

	// Reject the buffer if it is null/empty for any reason, or if the pointer
	// provided does not meet the alignment requirements of our header.
	if ((storage.data() == nullptr) \|\| storage.empty() \|\|
	(reinterpret_cast<uintptr_t>(storage.data()) % alignof(decltype(*hdr())))) {
	return;
	}

	// If the supplied storage is not enough to hold the header and even a
	// single trace entry, then just disable debug tracing by setting the header
	// location and the number of entries to nothing. In theory, these should
	// already be nullptr and 0, but we explicitly set them anyway since (again)
	// ASSERTing is not really an option given how early on in boot we are
	// likely to be right now.
	if (storage.size() < sizeof(Header) + sizeof(Entry)) {
	return;
	}

	// If this is a persistent trace and we have a recovery buffer, attempt to
	// recover the log from our storage before proceeding to re-init our trace
	// storage.
	storage_ = storage;
	if constexpr (kRecoveryBufferSize > 0) {
	::memcpy(recovered_buf_, storage_.data(), ktl::min(sizeof(recovered_buf_), storage_.size()));
	}

	// Go ahead and initialize our header and the number of entries we can hold
	// in our log, then flush this out to physical RAM if this is a persistent
	// trace buffer.
	new (storage_.data()) Header();
	entry_cnt_ = static_cast<uint32_t>((saturate<uint32_t>(storage_.size()) - sizeof(Header)) /
	sizeof(Entry));
	CleanCache(storage_.data(), storage_.size());
	}

	ktl::span<uint8_t> GetLocation() const { return storage_; }

	void Invalidate() {
	if (hdr() != nullptr) {
	hdr()->magic = Header::kNoMagic;
	CleanCache(hdr(), sizeof(*hdr()));
	}
	}

	void Log(Entry& entry) {
	if (hdr() == nullptr) {
	return;
	}

	// Record the fact that there is now a trace operation in progress, making
	// sure that we remember to decrement this count when we exit this method.
	trace_ops_in_flight_.fetch_add(1, ktl::memory_order_acq_rel);
	auto cleanup =
	fit::defer([this]() { trace_ops_in_flight_.fetch_add(-1, ktl::memory_order_acq_rel); });

	// Try to reserve a slot to write a record into. This should only fail if
	// the tracing is temporarily disabled for dumping.
	ktl::optional<uint32_t> opt_wr = ReserveSlot();
	if (!opt_wr.has_value()) {
	return;
	}

	// Go ahead and finish filling out the entry, then copy the entry into the
	// main trace buffer, and (if enabled) into the per-cpu last entry slot in
	// the header. Please note 2 potentially subtle points about this:
	//
	// 1) We mutate the log entry passed to us by the caller to finish filling
	// it out, then record that entry in both places. It is important that
	// we don't copy the record into the main trace buffer and _then_ finish
	// filling out the record (copying it from the main trace buffer to the
	// per-cpu header slot afterwards). There is a small chance that between
	// these operations, the log ends up wrapping and our currently assigned
	// slot gets stomped (causing the per-cpu record to be corrupted).
	// 2) We need to disable preemption for the time period between when we
	// record the CPU ID in the trace entry, and when write that entry into
	// the per-cpu slot. Failure to do this could result in us recording CPU
	// X in the entry, but then being moved to CPU Y before writing to the
	// per-cpu slot for X (and setting up a potential race between us and
	// whoever is running on CPU X now). Note that we cannot disable
	// preemption until after thread_init_early has been called, but at that
	// point in boot, interrupts are disabled and the secondary CPUs are not
	// running yet, so that should be OK. Also, we don't want to disable and
	// later attempt to re-enable preemption if interrupts are currently off
	// (as they would be when a spinlock is held) as it _could_ trip an
	// assert in the consistency checks for the preempt-disabler. If
	// interrupts are already disabled, we should be fine. We can't change
	// CPUs at that point in time anyway.
	//
	const uint32_t wr = opt_wr.value();
	{
	const bool disable_preemption = after_thread_init_early_ && !arch_ints_disabled();
	if (disable_preemption) {
	Thread::Current::preemption_state().PreemptDisable();
	}

	if constexpr (Config::kUseMonoTimestamps == UseMonoTimestamps::Yes) {
	entry.ts_ticks = current_mono_ticks();
	} else {
	entry.ts_ticks = current_boot_ticks();
	}
	if (entry.ts_ticks == 0) {
	entry.ts_ticks = kZeroReplacement;
	}

	entry.cpu_id = arch_curr_cpu_num();
	if constexpr (Config::kUseLargeEntries == UseLargeEntries::Yes) {
	entry.tid = after_thread_init_early_ ? Thread::Current::Get()->tid() : kUnknownTid;
	}

	hdr()->entries[wr] = entry;

	if constexpr (Config::kLastEntryStorage > 0) {
	if (entry.cpu_id < ktl::size(hdr()->last_cpu_entries_)) {
	hdr()->last_cpu_entries_[entry.cpu_id] = entry;
	}
	}

	if (disable_preemption) {
	Thread::Current::preemption_state().PreemptReenable();
	}
	}

	// Flush the header and the entry if this is a persistent trace.
	CleanCache(hdr(), sizeof(*hdr()));
	CleanCache(hdr()->entries + wr, sizeof(Entry));
	}

	// \|timeout\| controls how long this method will wait (spin) for other threads
	// to complete in progress writes before continuing on and dumping the buffer.
	void Dump(zx_duration_boot_t timeout) {
	if (hdr() == nullptr) {
	hooks_.PrintWarning("No debug trace buffer was ever configured\n");
	return;
	}

	// Disable tracing and give any thread currently in the process of writing a
	// record some time to get out of the way. Note that this is a best effort
	// approach to disabling the tracing during our dump. It is important that
	// debug tracing remain lockless at all times. The worst case scenario here
	// is that we end up with a partially garbled trace record.
	SetTraceEnabled(false);

	const affine::Ratio ticks_to_time_ratio = timer_get_ticks_to_time_ratio();
	const zx_instant_boot_ticks_t deadline =
	zx_ticks_add_ticks(current_boot_ticks(), ticks_to_time_ratio.Inverse().Scale(timeout));
	while ((trace_ops_in_flight_.load(ktl::memory_order_acquire) > 0) &&
	(current_boot_ticks() < deadline)) {
	// just spin while we wait.
	arch::Yield();
	}

	// Print a warning if we never saw the in flight op-count hit zero, then go
	// ahead and dump the current buffer.
	if (current_boot_ticks() >= deadline) {
	hooks_.PrintWarning(
	"Warning: ops in flight was never observed at zero while waiting to dump the current "
	"trace buffer. Some trace records might be corrupt.\n");
	}

	ktl::span<const uint8_t> data{reinterpret_cast<const uint8_t*>(hdr()),
	sizeof(hdr()) + (sizeof(Entry) entry_cnt_)};
	Dump(data, TraceBufferType::Current);

	// Finally, go ahead and re-enable tracing.
	SetTraceEnabled(true);
	}

	void DumpRecovered() {
	if constexpr (kRecoveryBufferSize > 0) {
	Dump({recovered_buf_, sizeof(recovered_buf_)}, TraceBufferType::Recovered);
	} else {
	hooks_.PrintWarning(
	"Debug tracing is not configured for persistent tracing. There is no recovered buffer "
	"to dump.\n");
	}
	}

	private:
	// Tests are allowed to peek at our private state.
	friend struct ::jtrace::tests;

	static constexpr uint32_t kTraceDisabledFlag = 0x80000000;
	static constexpr uint32_t kRecoveryBufferSize =
	(Config::kIsPersistent == jtrace::IsPersistent::Yes) ? Config::kTargetBufferSize : 0;

	static inline void CleanCache(void* ptr, size_t len) {
	// Trace data only needs to be flushed to physical RAM if the trace is meant
	// to be persistent.
	if constexpr (Config::kIsPersistent == jtrace::IsPersistent::Yes) {
	arch_clean_cache_range(reinterpret_cast<vaddr_t>(ptr), len);
	}
	}

	inline Header* hdr() { return reinterpret_cast<Header*>(storage_.data()); }

	ktl::optional<uint32_t> ReserveSlot() {
	uint32_t wr, next_wr;
	do {
	wr = hdr()->wr.load(ktl::memory_order_acquire);

	if (wr & kTraceDisabledFlag) {
	return ktl::nullopt;
	}

	next_wr = (wr + 1) % entry_cnt_;
	} while (!hdr()->wr.compare_exchange_weak(wr, next_wr, ktl::memory_order_acq_rel));

	return wr;
	}

	void SetTraceEnabled(bool enabled) {
	uint32_t wr, next_wr;
	do {
	wr = hdr()->wr.load(ktl::memory_order_acquire);
	next_wr = enabled ? (wr & ~kTraceDisabledFlag) : (wr \| kTraceDisabledFlag);
	} while (!hdr()->wr.compare_exchange_weak(wr, next_wr));
	}

	void Dump(ktl::span<const uint8_t> buf, TraceBufferType buf_type) {
	auto dump_corrupted_log = fit::defer([this, buf]() {
	hooks_.PrintWarning("JTRACE: Dumping corrupted log\n");
	hooks_.Hexdump(buf.data(), buf.size());
	});

	const size_t total_size = (sizeof(hdr()) + (entry_cnt_ sizeof(Entry)));
	if (total_size > buf.size()) {
	hooks_.PrintWarning("JTRACE: recovery buffer too small (%zu) to hold %u entries\n",
	buf.size(), entry_cnt_);
	return;
	}

	const Header* hdr = reinterpret_cast<const Header*>(buf.data());
	const Entry* entries = hdr->entries;
	if (hdr->magic == Header::kNoMagic) {
	hooks_.PrintInfo("JTRACE: Log appears clean, not dumping it (recoverd %p main %p len %zu)\n",
	buf.data(), this->hdr(), total_size);
	dump_corrupted_log.cancel();
	return;
	}

	const uint32_t wr = hdr->wr.load() & ~kTraceDisabledFlag;
	if ((hdr->magic != Header::kMagic) \|\| (wr >= entry_cnt_)) {
	hooks_.PrintWarning("JTRACE: Bad header: Magic 0x%08x Wr %u Entries %u\n", hdr->magic,
	hdr->wr.load(), entry_cnt_);
	return;
	}

	dump_corrupted_log.cancel();

	// Figure out how many entries we will dump, and where to start dumping
	// from. We skip any initial entries which have a timestamp of zero. We
	// never deliberately write a timestamps of zero, meaning that the entries
	// are skipping were never written, because the trace never wrapped.
	uint32_t rd = wr;
	uint32_t todo = entry_cnt_;
	while (todo) {
	const auto& e = entries[rd];
	if (e.ts_ticks != 0) {
	break;
	}
	rd = (rd + 1) % entry_cnt_;
	--todo;
	}

	auto ConvertTimestamp = [](const Entry& e) -> zx_time_t {
	const affine::Ratio ticks_to_time_ratio = timer_get_ticks_to_time_ratio();
	const zx_ticks_t ts = (e.ts_ticks == kZeroReplacement) ? 0 : e.ts_ticks;
	return ticks_to_time_ratio.Scale(ts);
	};

	if (todo) {
	hooks_.PrintInfo("JTRACE: Recovered %u/%u entries\n", todo, entry_cnt_);
	zx_time_t prev_ts = ConvertTimestamp(entries[rd]);

	for (; todo != 0; --todo) {
	const auto& e = entries[rd];
	const zx_time_t ts = ConvertTimestamp(entries[rd]);

	hooks_.PrintTraceEntry(e, buf_type, ts, ts - prev_ts);
	prev_ts = ts;
	rd = (rd + 1) % entry_cnt_;
	}

	// If we are configured to track per-cpu last events, go ahead and print
	// them out.
	if constexpr (Config::kLastEntryStorage > 0) {
	hooks_.PerCpuDumpStarted();
	hooks_.PrintInfo("\n");
	hooks_.PrintInfo("JTRACE: Last recorded per-CPU events.\n");

	if (Config::kLastEntryStorage != arch_max_num_cpus()) {
	hooks_.PrintWarning(
	"JTRACE: Warning! Configured per-cpu last entry count (%zu) does not match target's "
	"number of CPUs (%u)\n",
	Config::kLastEntryStorage, arch_max_num_cpus());
	}

	for (const Entry& e : hdr->last_cpu_entries_) {
	zx_time_t ts = ConvertTimestamp(e);
	hooks_.PrintTraceEntry(e, buf_type, ts);
	}
	}

	const int64_t last_sec = prev_ts / ZX_SEC(1);
	const int64_t last_nsec = prev_ts % ZX_SEC(1);
	hooks_.PrintInfo("\n");
	hooks_.PrintInfo("JTRACE: Last log timestamp [%4ld.%09ld]\n", last_sec, last_nsec);
	} else {
	hooks_.PrintInfo("JTRACE: no entries\n");
	}
	}

	// We never want to deliberately log a timestamp of zero. The buffer is
	// filled with zeros at the start, and we skip entries with zero time stamps
	// when trying to find the read pointer during a dump operation.
	// Unfortunately, if JTRACE entries are being created before the clock has
	// been selected, the time they are going to get is always 0. So, instead, we
	// replace that value with this constant instead, and substitute back again
	// during the dump.
	static inline constexpr zx_ticks_t kZeroReplacement = ktl::numeric_limits<zx_ticks_t>::min();

	TraceHooks& hooks_;
	ktl::span<uint8_t> storage_{};
	uint32_t entry_cnt_{0};
	ktl::atomic<uint32_t> trace_ops_in_flight_{0};
	bool after_thread_init_early_ = false;
	alignas(Header) uint8_t recovered_buf_[kRecoveryBufferSize];
	};

	} // namespace jtrace

	#endif // ZIRCON_KERNEL_LIB_JTRACE_JTRACE_INTERNAL_H_