blob: 15bd2b1edd34608f05731225736b0a2a54da8a9c [file] [log] [blame]
// Copyright 2012 Google Inc. All Rights Reserved.
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
#include <windows.h> // NOLINT
#include <stdio.h>
#include <vector>
#include "base/at_exit.h"
#include "base/command_line.h"
#include "base/file_util.h"
#include "base/logging.h"
#include "base/files/file_path.h"
#include "base/threading/simple_thread.h"
#include "base/win/event_trace_consumer.h"
#include "base/win/event_trace_controller.h"
#include "base/win/scoped_handle.h"
#include "base/win/windows_version.h"
#include "syzygy/common/indexed_frequency_data.h"
#include "syzygy/trace/parse/parser.h"
#include "syzygy/trace/service/service.h"
namespace {
using trace::parser::Parser;
using trace::parser::ParseEventHandler;
using trace::parser::ModuleInformation;
const char* GetIndexedDataTypeStr(uint8 data_type) {
const char* ret = NULL;
switch (data_type) {
case common::IndexedFrequencyData::BASIC_BLOCK_ENTRY:
ret = "basic-block entry counts";
break;
case common::IndexedFrequencyData::COVERAGE:
ret = "coverage entry counts";
break;
case common::IndexedFrequencyData::BRANCH:
ret = "branch entry counts";
break;
case common::IndexedFrequencyData::JUMP_TABLE:
ret = "jump-table case counts";
break;
default:
NOTREACHED();
break;
}
return ret;
}
class TraceFileDumper : public ParseEventHandler {
public:
explicit TraceFileDumper(FILE* file)
: file_(file ? file : stdout),
indentation_("") {
}
void PrintFunctionEvent(const char* event_type,
base::Time time,
DWORD process_id,
DWORD thread_id,
const TraceEnterExitEventData* data) {
DCHECK(event_type != NULL);
DCHECK(data != NULL);
DCHECK(data->function != NULL);
::fprintf(file_,
"[%012lld] %s%s: process-id=%d; thread-id=%d; address=0x%08X\n",
time.ToInternalValue(),
indentation_,
event_type,
process_id,
thread_id,
data->function);
}
void PrintModuleEvent(const char* event_type,
base::Time time,
DWORD process_id,
DWORD thread_id,
const TraceModuleData* data) {
DCHECK(event_type != NULL);
DCHECK(data != NULL);
DCHECK(data->module_base_addr != NULL);
::fprintf(file_,
"[%012lld] %s: process-id=%d; thread-id=%d;"
" module-name='%ls';"
" module-addr=0x%08X; module-size=%d\n",
time.ToInternalValue(),
event_type,
process_id,
thread_id,
data->module_name,
data->module_base_addr,
data->module_base_size);
}
void PrintOsVersionInfo(base::Time time,
const OSVERSIONINFOEX& os_version_info) {
::fprintf(file_,
"[%012lld] %sOsVersionInfo: platform_id=%d; product_type=%d; "
"version=%d.%d; build=%d; service_pack=%d.%d\n",
time.ToInternalValue(),
indentation_,
os_version_info.dwPlatformId,
os_version_info.wProductType,
os_version_info.dwMajorVersion,
os_version_info.dwMinorVersion,
os_version_info.dwBuildNumber,
os_version_info.wServicePackMajor,
os_version_info.wServicePackMinor);
}
void PrintSystemInfo(base::Time time, const SYSTEM_INFO& system_info) {
::fprintf(file_,
"[%012lld] %sSystemInfo: cpu_arch=%d; cpu_count=%d; "
"cpu_level=%d; cpu_rev=%d\n",
time.ToInternalValue(),
indentation_,
system_info.wProcessorArchitecture,
system_info.dwNumberOfProcessors,
system_info.wProcessorLevel,
system_info.wProcessorRevision);
}
void PrintMemoryStatus(base::Time time, const MEMORYSTATUSEX& memory_status) {
::fprintf(file_,
"[%012lld] %sMemoryStatus: load=%d; total_phys=%lld; "
"avail_phys=%lld\n",
time.ToInternalValue(),
indentation_,
memory_status.dwMemoryLoad,
memory_status.ullTotalPhys,
memory_status.ullAvailPhys);
}
void PrintClockInfo(base::Time time,
const trace::common::ClockInfo& clock_info) {
::fprintf(file_,
"[%012lld] %sClockInfo: file_time=0x%08X%08X; "
"ticks_reference=%llu; tsc_reference=%llu; "
"ticks_info.frequency=%llu; ticks_info.resolution=%llu; "
"tsc_info.frequency=%llu; tsc_info.resolution=%llu\n",
time.ToInternalValue(),
indentation_,
clock_info.file_time.dwHighDateTime,
clock_info.file_time.dwLowDateTime,
clock_info.ticks_reference,
clock_info.tsc_reference,
clock_info.ticks_info.frequency,
clock_info.ticks_info.resolution,
clock_info.tsc_info.frequency,
clock_info.tsc_info.resolution);
}
void PrintEnvironmentString(base::Time time,
const std::wstring& key,
const std::wstring& value) {
::fprintf(file_,
"[%012lld] %sEnvironment: %ls=%ls\n",
time.ToInternalValue(),
indentation_,
key.c_str(),
value.c_str());
}
void PrintEnvironmentStrings(base::Time time,
const TraceEnvironmentStrings& env_strings) {
for (size_t i = 0; i < env_strings.size(); ++i)
PrintEnvironmentString(time, env_strings[i].first, env_strings[i].second);
}
virtual void OnProcessStarted(base::Time time,
DWORD process_id,
const TraceSystemInfo* data) {
::fprintf(file_,
"[%012lld] OnProcessStarted: process-id=%d\n",
time.ToInternalValue(),
process_id);
if (data == NULL)
return;
indentation_ = " ";
PrintOsVersionInfo(time, data->os_version_info);
PrintSystemInfo(time, data->system_info);
PrintMemoryStatus(time, data->memory_status);
PrintClockInfo(time, data->clock_info);
PrintEnvironmentStrings(time, data->environment_strings);
indentation_ = "";
}
virtual void OnProcessEnded(base::Time time, DWORD process_id) {
::fprintf(file_,
"[%012lld] OnProcessEnded: process-id=%d\n",
time.ToInternalValue(),
process_id);
}
virtual void OnFunctionEntry(base::Time time,
DWORD process_id,
DWORD thread_id,
const TraceEnterExitEventData* data) {
PrintFunctionEvent("OnFunctionEntry", time, process_id, thread_id, data);
}
virtual void OnFunctionExit(base::Time time,
DWORD process_id,
DWORD thread_id,
const TraceEnterExitEventData* data) {
PrintFunctionEvent("OnFunctionEntry", time, process_id, thread_id, data);
}
virtual void OnBatchFunctionEntry(base::Time time,
DWORD process_id,
DWORD thread_id,
const TraceBatchEnterData* data) {
DCHECK(data != NULL);
DCHECK_EQ(thread_id, data->thread_id);
::fprintf(file_,
"[%012lld] OnBatchFunctionEntry: " \
"process-id=%d; thread-id=%d; num-calls=%d\n",
time.ToInternalValue(),
process_id,
thread_id,
data->num_calls);
// Explode the batch event into individual function entry events.
TraceEnterExitEventData new_data = {};
indentation_ = " ";
for (size_t i = 0; i < data->num_calls; ++i) {
new_data.function = data->calls[i].function;
OnFunctionEntry(time, process_id, thread_id, &new_data);
}
indentation_ = "";
}
virtual void OnProcessAttach(base::Time time,
DWORD process_id,
DWORD thread_id,
const TraceModuleData* data) {
PrintModuleEvent("OnProcessAttach", time, process_id, thread_id, data);
}
virtual void OnProcessDetach(base::Time time,
DWORD process_id,
DWORD thread_id,
const TraceModuleData* data) {
PrintModuleEvent("OnProcessDetach", time, process_id, thread_id, data);
}
virtual void OnThreadAttach(base::Time time,
DWORD process_id,
DWORD thread_id,
const TraceModuleData* data) {
PrintModuleEvent("OnThreadAttach", time, process_id, thread_id, data);
}
virtual void OnThreadDetach(base::Time time,
DWORD process_id,
DWORD thread_id,
const TraceModuleData* data) {
PrintModuleEvent("OnThreadDetach", time, process_id, thread_id, data);
}
virtual void OnInvocationBatch(base::Time time,
DWORD process_id,
DWORD thread_id,
size_t num_invocations,
const TraceBatchInvocationInfo* data) {
DCHECK(data != NULL);
::fprintf(file_,
"OnInvocationBatch: process-id=%d; thread-id=%d;\n",
process_id,
thread_id);
for (size_t i = 0; i < num_invocations; ++i) {
const InvocationInfo& invocation = data->invocations[i];
if ((invocation.flags & kCallerIsSymbol) != 0) {
::fprintf(file_,
" caller_sym=0x%X, offs=%d;",
invocation.caller_symbol_id,
invocation.caller_offset);
} else {
::fprintf(file_,
" caller=0x%08X;",
invocation.caller);
}
if ((invocation.flags & kFunctionIsSymbol) != 0) {
::fprintf(file_, " function_sym=0x%X;", invocation.function_symbol_id);
} else {
::fprintf(file_, " function=0x%08X;", invocation.function);
}
::fprintf(file_,
" num-calls=%d;\n"
" cycles-min=%lld; cycles-max=%lld; cycles-sum=%lld\n",
data->invocations[i].num_calls,
data->invocations[i].cycles_min,
data->invocations[i].cycles_max,
data->invocations[i].cycles_sum);
}
}
virtual void OnThreadName(base::Time time,
DWORD process_id,
DWORD thread_id,
const base::StringPiece& thread_name) OVERRIDE {
::fprintf(file_, "OnThreadName: process-id=%d; thread-id=%d;\n"
" name=%s\n",
process_id, thread_id, thread_name.as_string().c_str());
}
virtual void OnIndexedFrequency(
base::Time time,
DWORD process_id,
DWORD thread_id,
const TraceIndexedFrequencyData* data) OVERRIDE {
DCHECK(data != NULL);
::fprintf(file_,
"OnIndexedFrequency: process-id=%d; thread-id=%d;\n"
" module-base-addr=0x%08X; module-base-size=%d\n"
" module-checksum=0x%08X; module-time-date-stamp=0x%08X\n"
" frequency-size=%d; num_columns=%d; num-entries=%d;\n"
" data-type=%s;\n",
process_id,
thread_id,
data->module_base_addr,
data->module_base_size,
data->module_checksum,
data->module_time_date_stamp,
data->frequency_size,
data->num_columns,
data->num_entries,
GetIndexedDataTypeStr(data->data_type));
}
virtual void OnDynamicSymbol(DWORD process_id,
uint32 symbol_id,
const base::StringPiece& symbol_name) OVERRIDE {
::fprintf(file_, "OnDynamicSymbol: process-id=%d;\n"
" symbol_id=%d\n"
" symbol_name=%s\n",
process_id, symbol_id, symbol_name.as_string().c_str());
}
virtual void OnSampleData(base::Time Time,
DWORD process_id,
const TraceSampleData* data) OVERRIDE {
DCHECK(data != NULL);
uint64 samples = 0;
for (uint32 i = 0; i < data->bucket_count; ++i)
samples += data->buckets[i];
::fprintf(file_,
"OnSampleData: process-id=%d; module-base-addr=0x%08X;\n"
" module-size=%d; module-checksum=0x%08X;\n"
" module-time-date-stamp=0x%08X; bucket-size=%d;\n"
" bucket-start=0x%08x; bucket-count=%d;\n"
" sampling-start-time=0x%016llx;\n"
" sampling-end-time=0x%016llx; sampling-interval=0x%016llx;\n"
" samples=%lld\n",
process_id,
data->module_base_addr,
data->module_size,
data->module_checksum,
data->module_time_date_stamp,
data->bucket_size,
data->bucket_start,
data->bucket_count,
data->sampling_start_time,
data->sampling_end_time,
data->sampling_interval,
samples);
}
private:
FILE* file_;
const char* indentation_;
DISALLOW_COPY_AND_ASSIGN(TraceFileDumper);
};
bool DumpTraceFiles(FILE* out_file,
const std::vector<base::FilePath>& file_paths) {
Parser parser;
TraceFileDumper dumper(out_file);
if (!parser.Init(&dumper))
return false;
std::vector<base::FilePath>::const_iterator iter = file_paths.begin();
for (; iter != file_paths.end(); ++iter) {
if (!parser.OpenTraceFile(*iter))
return false;
}
return parser.Consume() && !parser.error_occurred();
}
} // namespace
int main(int argc, const char** argv) {
base::AtExitManager at_exit_manager;
CommandLine::Init(argc, argv);
logging::LoggingSettings settings;
settings.logging_dest = logging::LOG_TO_SYSTEM_DEBUG_LOG;
settings.lock_log = logging::DONT_LOCK_LOG_FILE;
settings.delete_old = logging::APPEND_TO_OLD_LOG_FILE;
if (!logging::InitLogging(settings))
return 1;
CommandLine* cmd_line = CommandLine::ForCurrentProcess();
CHECK(cmd_line != NULL);
std::vector<base::FilePath> trace_file_paths;
for (size_t i = 0; i < cmd_line->GetArgs().size(); ++i)
trace_file_paths.push_back(base::FilePath(cmd_line->GetArgs()[i]));
if (trace_file_paths.empty()) {
LOG(ERROR) << "No trace file paths specified.";
::fprintf(stderr,
"Usage: %ls [--out=OUTPUT] TRACE_FILE(s)...\n\n",
cmd_line->GetProgram().value().c_str());
return 1;
}
base::FilePath out_file_path(cmd_line->GetSwitchValuePath("out"));
base::ScopedFILE out_file;
if (!out_file_path.empty()) {
out_file.reset(base::OpenFile(out_file_path, "w"));
if (out_file.get() == NULL) {
LOG(ERROR) << "Failed to open output file: '" << out_file_path.value()
<< "'.";
return 1;
}
}
if (!DumpTraceFiles(out_file.get(), trace_file_paths)) {
LOG(ERROR) << "Failed to dump trace files.";
return 1;
}
return 0;
}