+++ /dev/null
-//
-// EventPrinting.hpp
-// kdprof
-//
-// Created by James McIlree on 4/20/13.
-// Copyright (c) 2013 Apple. All rights reserved.
-//
-
-#ifndef kdprof_ParallelPrinting_hpp
-#define kdprof_ParallelPrinting_hpp
-
-void print_event_header(const Globals& globals, bool is_64_bit);
-
-template <typename SIZE>
-char* print_event(char* buf, char* buf_end, const Globals& globals, const Machine<SIZE>& machine, const KDEvent<SIZE>& event, uintptr_t event_index)
-{
- // Header is...
- //
- // [Index] Time Type Code arg1 arg2 arg3 arg4 thread cpu# command/IOP-name pid
- // 8 16 4 34 8/16 8/16 8/16 8/16 10 4 16 6
- //
- // For now, each column is folding up the "after" spacing in a single printf, IOW
- //
- // buf += snprintf(buf, buf_end - buf, "%8s ", "COL"); /* + 2 spaces */
- //
- // Not:
- //
- // buf += snprintf(buf, buf_end - buf, "%8s", "COL");
- // buf += snprintf(buf, buf_end - buf, " "); /* 2 spaces */
-
- ASSERT(event.cpu() > -1 && event.cpu() < machine.cpus().size(), "cpu_id out of range");
- const MachineCPU<SIZE>& cpu = machine.cpus()[event.cpu()];
-
- //
- // Okay, here is how snprintf works.
- //
- // char buf[2];
- //
- // snprintf(buf, 0, "a"); // Returns 1, buf is unchanged.
- // snprintf(buf, 1, "a"); // Returns 1, buf = \0
- // snprintf(buf, 2, "a"); // Returns 1, buf = 'a', \0
-
- //
- // If we cannot print successfully, we return the orignal pointer.
- //
- char* orig_buf = buf;
-
- //
- // [Index]
- //
- if (globals.should_print_event_index()) {
- buf += snprintf(buf, buf_end - buf, "%8llu ", (uint64_t)event_index);
- }
-
- if (buf >= buf_end)
- return orig_buf;
-
- //
- // Time
- //
- if (globals.should_print_mach_absolute_timestamps()) {
- if (globals.beginning_of_time().value() == 0)
- buf += snprintf(buf, buf_end - buf, "%16llX ", (event.timestamp() - globals.beginning_of_time()).value());
- else
- buf += snprintf(buf, buf_end - buf, "%16llu ", (event.timestamp() - globals.beginning_of_time()).value());
- } else {
- NanoTime ntime = (event.timestamp() - globals.beginning_of_time()).nano_time(globals.timebase());
- buf += snprintf(buf, buf_end - buf, "%16.2f ", (double)ntime.value() / 1000.0);
- }
-
- if (buf >= buf_end)
- return orig_buf;
-
- //
- // Type Code
- //
- const char* type = event.is_func_start() ? "beg" : (event.is_func_end() ? "end" : "---");
- auto trace_code_it = globals.trace_codes().find(event.dbg_cooked());
- if (cpu.is_iop() || !globals.should_print_symbolic_event_codes() || trace_code_it == globals.trace_codes().end()) {
- buf += snprintf(buf, buf_end - buf, "%4s %-34x ", type, event.dbg_cooked());
- } else {
- buf += snprintf(buf, buf_end - buf, "%4s %-34s ", type, trace_code_it->second.c_str());
- }
-
- if (buf >= buf_end)
- return orig_buf;
-
- //
- // arg1
- //
- if (event.dbg_class() == DBG_IOKIT && event.dbg_subclass() == DBG_IOPOWER) {
- std::string kext_name = event.arg1_as_string();
- std::reverse(kext_name.begin(), kext_name.end());
-
- if (SIZE::is_64_bit)
- buf += snprintf(buf, buf_end - buf, "%-16s ", kext_name.c_str());
- else
- buf += snprintf(buf, buf_end - buf, "%-8s ", kext_name.c_str());
- } else {
- if (SIZE::is_64_bit)
- buf += snprintf(buf, buf_end - buf, "%-16llX ", (uint64_t)event.arg1());
- else
- buf += snprintf(buf, buf_end - buf, "%-8x ", (uint32_t)event.arg1());
- }
-
- if (buf >= buf_end)
- return orig_buf;
-
- //
- // Profiling showed that the repeated snprintf calls were hot, rolling them up is ~2.5% per on a HUGE file.
- //
- // arg2 arg3 arg4 thread cpu
- //
- if (SIZE::is_64_bit)
- buf += snprintf(buf, buf_end - buf, "%-16llX %-16llX %-16llX %10llX %4u ", (uint64_t)event.arg2(), (uint64_t)event.arg3(), (uint64_t)event.arg4(), (uint64_t)event.tid(), event.cpu());
- else
- buf += snprintf(buf, buf_end - buf, "%-8x %-8x %-8x %10llX %4u ", (uint32_t)event.arg2(), (uint32_t)event.arg3(), (uint32_t)event.arg4(), (uint64_t)event.tid(), event.cpu());
-
- if (buf >= buf_end)
- return orig_buf;
-
- //
- // command & pid (handled together due to IOP not printing a pid
- //
- if (cpu.is_iop()) {
- // We print the IOP name instead of a command
- buf += snprintf(buf, buf_end - buf, "%-16s\n", cpu.name());
- } else {
- if (const MachineThread<SIZE>* thread = machine.thread(event.tid(), event.timestamp())) {
- buf += snprintf(buf, buf_end - buf, "%-16s %-6d\n", thread->process().name(), thread->process().pid());
- } else {
- buf += snprintf(buf, buf_end - buf, "%-16s %-6s\n", "?????", "???");
- }
- }
-
- // Still need to check this, its an error if we overflow on the last print!
- if (buf >= buf_end)
- return orig_buf;
-
- return buf;
-}
-
-template <typename SIZE>
-char* print_event_range_to_buffer(const Globals& globals, const Machine<SIZE>& machine, TRange<uintptr_t> range, MemoryBuffer<char>& buffer ) {
- char* cursor = buffer.data();
- char* cursor_end = cursor + buffer.capacity();
-
- if (const KDEvent<SIZE>* events = machine.events()) {
- ASSERT(TRange<uintptr_t>(0, machine.event_count()).contains(range), "Sanity");
- for (uintptr_t index = range.location(); index < range.max(); ++index) {
- char* temp = print_event(cursor, cursor_end, globals, machine, events[index], index);
- if (temp != cursor)
- cursor = temp;
- else {
- // Changing the capacity will invalidate the cursor
- ptrdiff_t offset = cursor - buffer.data();
- buffer.set_capacity(buffer.capacity()*2);
- cursor = buffer.data() + offset;
- cursor_end = buffer.data() + buffer.capacity();
- }
- }
- }
-
- return cursor;
-}
-
-class PrintWorkUnit {
- protected:
- MemoryBuffer<char> _buffer;
- TRange<uintptr_t> _event_range;
- char* _buffer_end;
-
- // We do not want work units copied.
- PrintWorkUnit(const PrintWorkUnit& that) = delete;
- PrintWorkUnit& operator=(const PrintWorkUnit& other) = delete;
-
- public:
- PrintWorkUnit(MemoryBuffer<char>&& buffer, TRange<uintptr_t> event_range, char* buffer_end) :
- _buffer(std::move(buffer)),
- _event_range(event_range),
- _buffer_end(buffer_end)
- {
- ASSERT(_buffer.capacity(), "Sanity");
- ASSERT(_buffer.data(), "Sanity");
- ASSERT(!_buffer_end || _buffer_end > _buffer.data(), "Sanity");
- ASSERT(!_buffer_end || (_buffer_end < _buffer.data() + _buffer.capacity()), "Sanity");
- }
-
- MemoryBuffer<char>& buffer() { return _buffer; }
-
- TRange<uintptr_t> event_range() { return _event_range; }
- void set_event_range(TRange<uintptr_t> range) { _event_range = range; }
-
- char* buffer_end() const { return _buffer_end; }
- void set_buffer_end(char* buffer_end) { _buffer_end = buffer_end; }
-};
-
-template <typename SIZE>
-class PrintProducer {
- protected:
- const Globals& _globals;
- const Machine<SIZE>& _machine;
- uintptr_t _start_index;
- uintptr_t _end_index;
- uintptr_t _chunk_size;
-
- public:
- PrintProducer(const Globals& globals, const Machine<SIZE>& machine, uintptr_t chunk_size) :
- _globals(globals),
- _machine(machine),
- _chunk_size(chunk_size)
- {
- _start_index = 0;
- _end_index = machine.event_count();
-
- if (globals.is_summary_start_set() || globals.is_summary_stop_set()) {
- AbsInterval machine_timespan = machine.timespan();
-
- KDEvent<SIZE> start_event(globals.summary_start(machine_timespan));
- auto it = std::lower_bound(machine.events(), machine.events() + _end_index, start_event);
- ASSERT(&*it >= machine.events(), "Returned start index lower than start");
- _start_index = std::distance(machine.events(), it);
-
- KDEvent<SIZE> end_event(globals.summary_stop(machine_timespan));
- it = std::lower_bound(machine.events(), machine.events() + _end_index, end_event);
- ASSERT(&*it <= machine.events() + _end_index, "Returned end index greater than end");
- _end_index = std::distance(machine.events(), it);
-
- ASSERT(_start_index <= _end_index, "start index is > end index");
- }
- }
-
- bool produce(PrintWorkUnit& work_unit) {
- // Claim a chunk of work to do
- uintptr_t orig_start_index, new_start_index;
- do {
- orig_start_index = _start_index;
- new_start_index = orig_start_index + std::min(_chunk_size, _end_index - orig_start_index);
- } while (orig_start_index < _end_index && !OSAtomicCompareAndSwapPtrBarrier((void*)orig_start_index, (void *)new_start_index, (void * volatile *)&_start_index));
-
- // Did we claim work?
- if (orig_start_index < _end_index) {
- TRange<uintptr_t> event_range(orig_start_index, new_start_index - orig_start_index);
- char* end = print_event_range_to_buffer(_globals, _machine, event_range, work_unit.buffer());
-
- work_unit.set_event_range(event_range);
- work_unit.set_buffer_end(end);
- return true;
- }
-
- return false;
- }
-
- uintptr_t start_index() const { return _start_index; }
-};
-
-template <typename SIZE>
-class PrintConsumer {
- protected:
- const Globals& _globals;
- uintptr_t _write_index;
- std::mutex _write_mutex;
- std::condition_variable _write_condition;
-
- public:
- PrintConsumer(const Globals& globals, const Machine<SIZE>& machine, uintptr_t start_index) :
- _globals(globals),
- _write_index(start_index)
- {
- }
-
- void consume(PrintWorkUnit& work_unit) {
- std::unique_lock<std::mutex> guard(_write_mutex);
- _write_condition.wait(guard, [&](){ return work_unit.event_range().location() == this->_write_index; });
-
- ASSERT(work_unit.event_range().location() == _write_index, "Sanity");
-
- char* data = work_unit.buffer().data();
- size_t bytes = work_unit.buffer_end() - data;
- write(_globals.output_fd(), work_unit.buffer().data(), bytes);
- _write_index = work_unit.event_range().max();
-
- _write_condition.notify_all();
- }
-};
-
-template <typename SIZE>
-uintptr_t print_machine_events(const Globals& globals, const Machine<SIZE>& machine) {
- print_event_header(globals, SIZE::is_64_bit);
-
- if (const KDEvent<SIZE>* events = machine.events()) {
- if (uintptr_t event_count = machine.event_count()) {
-
- //
- // We want to chunk this up into reasonably sized pieces of work.
- // Because each piece of work can potentially accumulate a large
- // amount of memory, we need to limit the amount of work "in-flight".
- //
- uint32_t active_cpus = Kernel::active_cpu_count();
-
- uintptr_t chunk_size = 2000;
-
- PrintProducer<SIZE> producer(globals, machine, chunk_size);
- PrintConsumer<SIZE> consumer(globals, machine, producer.start_index());
-
- std::vector<std::thread> threads;
- for (uint32_t i=0; i<active_cpus; ++i) {
- threads.push_back(std::thread([&]() {
- PrintWorkUnit work_unit(MemoryBuffer<char>(160 * chunk_size), TRange<uintptr_t>(0, 0), (char*)NULL);
- while (producer.produce(work_unit)) {
- consumer.consume(work_unit);
- }
- }));
- }
-
- for(auto& thread : threads){
- thread.join();
- }
-
- uint32_t totalProcesses = 0;
- uint32_t totalThreads = 0;
-
- for (auto process : machine.processes()) {
- if (!process->is_created_by_previous_machine_state()) {
- totalProcesses++;
- }
- }
-
- for (auto thread : machine.threads()) {
- if (!thread->is_created_by_previous_machine_state()) {
- totalThreads++;
- }
- }
-
- dprintf(globals.output_fd(), "Total Events: %llu\n", (uint64_t)event_count);
- dprintf(globals.output_fd(), "Total Processes: %u\n", totalProcesses);
- dprintf(globals.output_fd(), "Total Threads: %u\n", totalThreads);
-
- return event_count;
- }
- }
-
- return 0;
-}
-
-#endif