Skip to content

Commit

Permalink
* Change output of trace_event log to JSON to enable easier integrati…
Browse files Browse the repository at this point in the history 
…on with visualization UI.

* Simple (manual) trace visualizer with some sample data.
* a few more trace events
* add process_util function for current process handle

Review URL: http://codereview.chromium.org/3086

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@2381 0039d316-1c4b-4281-b951-d872f2087c98
  • Loading branch information
erikkay@google.com committed Sep 18, 2008
1 parent 37cbdcc commit 113ab13
Show file tree
Hide file tree
Showing 9 changed files with 1,407 additions and 15 deletions.
3 changes: 3 additions & 0 deletions base/process_util.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -32,6 +32,9 @@ namespace process_util {
// Returns the id of the current process.
int GetCurrentProcId();

// Returns the ProcessHandle of the current process.
ProcessHandle GetCurrentProcessHandle();

// Returns the unique ID for the specified process. This is functionally the
// same as Windows' GetProcessId(), but works on versions of Windows before
// Win XP SP1 as well.
Expand Down
4 changes: 4 additions & 0 deletions base/process_util_posix.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,10 @@ int GetCurrentProcId() {
return getpid();
}

ProcessHandle GetCurrentProcessHandle() {
return GetCurrentProcId();
}

int GetProcId(ProcessHandle process) {
return process;
}
Expand Down
4 changes: 4 additions & 0 deletions base/process_util_win.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,10 @@ int GetCurrentProcId() {
return ::GetCurrentProcessId();
}

ProcessHandle GetCurrentProcessHandle() {
return ::GetCurrentProcess();
}

// Helper for GetProcId()
bool GetProcIdViaGetProcessId(ProcessHandle process, DWORD* id) {
// Dynamically get a pointer to GetProcessId().
Expand Down
26 changes: 20 additions & 6 deletions base/trace_event.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,8 @@ static const char* kEventTypeNames[] = {
static const wchar_t* kLogFileName = L"trace_%d.log";

TraceLog::TraceLog() : enabled_(false), log_file_(NULL) {
ProcessHandle proc = process_util::GetCurrentProcessHandle();
process_metrics_.reset(process_util::ProcessMetrics::CreateProcessMetrics(proc));
}

TraceLog::~TraceLog() {
Expand All @@ -46,8 +48,11 @@ bool TraceLog::Start() {
if (enabled_)
return true;
enabled_ = OpenLogFile();
if (enabled_)
if (enabled_) {
Log("var raw_trace_events = [\r\n");
trace_start_time_ = TimeTicks::Now();
timer_.Start(TimeDelta::FromMilliseconds(250), this, &TraceLog::Heartbeat);
}
return enabled_;
}

Expand All @@ -60,10 +65,17 @@ void TraceLog::StopTracing() {
void TraceLog::Stop() {
if (enabled_) {
enabled_ = false;
Log("];\r\n");
CloseLogFile();
timer_.Stop();
}
}

void TraceLog::Heartbeat() {
std::string cpu = StringPrintf("%d", process_metrics_->GetCPUUsage());
TRACE_EVENT_INSTANT("heartbeat.cpu", 0, cpu);
}

void TraceLog::CloseLogFile() {
if (log_file_) {
#if defined(OS_WIN)
Expand Down Expand Up @@ -105,7 +117,7 @@ bool TraceLog::OpenLogFile() {

void TraceLog::Trace(const std::string& name,
EventType type,
void* id,
const void* id,
const std::wstring& extra,
const char* file,
int line) {
Expand All @@ -116,7 +128,7 @@ void TraceLog::Trace(const std::string& name,

void TraceLog::Trace(const std::string& name,
EventType type,
void* id,
const void* id,
const std::string& extra,
const char* file,
int line) {
Expand All @@ -131,16 +143,18 @@ void TraceLog::Trace(const std::string& name,
TimeDelta delta = tick - trace_start_time_;
int64 usec = delta.InMicroseconds();
std::string msg =
StringPrintf("%I64d 0x%lx:0x%lx %s %s [0x%lx %s] <%s:%d>\r\n",
usec,
StringPrintf("{'pid':'0x%lx', 'tid':'0x%lx', 'type':'%s', "
"'name':'%s', 'id':'0x%lx', 'extra':'%s', 'file':'%s', "
"'line_number':'%d', 'usec_begin': %I64d},\r\n",
process_util::GetCurrentProcId(),
PlatformThread::CurrentId(),
kEventTypeNames[type],
name.c_str(),
id,
extra.c_str(),
file,
line);
line,
usec);

Log(msg);
}
Expand Down
19 changes: 14 additions & 5 deletions base/trace_event.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,8 +24,10 @@
#include <string>

#include "base/lock.h"
#include "base/scoped_ptr.h"
#include "base/singleton.h"
#include "base/time.h"
#include "base/timer.h"

// Use the following macros rather than using the TraceLog class directly as the
// underlying implementation may change in the future. Here's a sample usage:
Expand All @@ -40,7 +42,7 @@
#define TRACE_EVENT_BEGIN(name, id, extra) \
Singleton<base::TraceLog>::get()->Trace(name, \
base::TraceLog::EVENT_BEGIN, \
reinterpret_cast<void*>(id), \
reinterpret_cast<const void*>(id), \
extra, \
__FILE__, \
__LINE__)
Expand All @@ -50,7 +52,7 @@
#define TRACE_EVENT_END(name, id, extra) \
Singleton<base::TraceLog>::get()->Trace(name, \
base::TraceLog::EVENT_END, \
reinterpret_cast<void*>(id), \
reinterpret_cast<const void*>(id), \
extra, \
__FILE__, \
__LINE__)
Expand All @@ -59,7 +61,7 @@
#define TRACE_EVENT_INSTANT(name, id, extra) \
Singleton<base::TraceLog>::get()->Trace(name, \
base::TraceLog::EVENT_INSTANT, \
reinterpret_cast<void*>(id), \
reinterpret_cast<const void*>(id), \
extra, \
__FILE__, \
__LINE__)
Expand All @@ -77,6 +79,10 @@ typedef HANDLE FileHandle;
typedef FILE* FileHandle;
#endif

namespace process_util {
class ProcessMetrics;
}

namespace base {

class TraceLog {
Expand All @@ -97,13 +103,13 @@ class TraceLog {
// Log a trace event of (name, type, id) with the optional extra string.
void Trace(const std::string& name,
EventType type,
void* id,
const void* id,
const std::wstring& extra,
const char* file,
int line);
void Trace(const std::string& name,
EventType type,
void* id,
const void* id,
const std::string& extra,
const char* file,
int line);
Expand All @@ -119,12 +125,15 @@ class TraceLog {
void CloseLogFile();
bool Start();
void Stop();
void Heartbeat();
void Log(const std::string& msg);

bool enabled_;
FileHandle log_file_;
Lock file_lock_;
TimeTicks trace_start_time_;
scoped_ptr<process_util::ProcessMetrics> process_metrics_;
RepeatingTimer<TraceLog> timer_;
};

} // namespace base
Expand Down
10 changes: 6 additions & 4 deletions net/base/tcp_client_socket.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -157,6 +157,7 @@ int TCPClientSocket::Read(char* buf,
buffer_.len = buf_len;
buffer_.buf = buf;

TRACE_EVENT_BEGIN("socket.read", this, "");
// TODO(wtc): Remove the CHECKs after enough testing.
CHECK(WaitForSingleObject(overlapped_.hEvent, 0) == WAIT_TIMEOUT);
DWORD num, flags = 0;
Expand All @@ -165,6 +166,7 @@ int TCPClientSocket::Read(char* buf,
CHECK(WaitForSingleObject(overlapped_.hEvent, 0) == WAIT_OBJECT_0);
BOOL ok = WSAResetEvent(overlapped_.hEvent);
CHECK(ok);
TRACE_EVENT_END("socket.read", this, StringPrintf("%d bytes", num));
return static_cast<int>(num);
}
int err = WSAGetLastError();
Expand All @@ -187,6 +189,7 @@ int TCPClientSocket::Write(const char* buf,
buffer_.len = buf_len;
buffer_.buf = const_cast<char*>(buf);

TRACE_EVENT_BEGIN("socket.write", this, "");
// TODO(wtc): Remove the CHECKs after enough testing.
CHECK(WaitForSingleObject(overlapped_.hEvent, 0) == WAIT_TIMEOUT);
DWORD num;
Expand All @@ -195,6 +198,7 @@ int TCPClientSocket::Write(const char* buf,
CHECK(WaitForSingleObject(overlapped_.hEvent, 0) == WAIT_OBJECT_0);
BOOL ok = WSAResetEvent(overlapped_.hEvent);
CHECK(ok);
TRACE_EVENT_END("socket.write", this, StringPrintf("%d bytes", num));
return static_cast<int>(num);
}
int err = WSAGetLastError();
Expand Down Expand Up @@ -272,11 +276,9 @@ void TCPClientSocket::DidCompleteIO() {
socket_, &overlapped_, &num_bytes, FALSE, &flags);
WSAResetEvent(overlapped_.hEvent);
if (wait_state_ == WAITING_READ) {
TRACE_EVENT_INSTANT("socket.read", this,
StringPrintf("%d bytes", num_bytes));
TRACE_EVENT_END("socket.read", this, StringPrintf("%d bytes", num_bytes));
} else {
TRACE_EVENT_INSTANT("socket.write", this,
StringPrintf("%d bytes", num_bytes));
TRACE_EVENT_END("socket.write", this, StringPrintf("%d bytes", num_bytes));
}
wait_state_ = NOT_WAITING;
DoCallback(ok ? num_bytes : MapWinsockError(WSAGetLastError()));
Expand Down
19 changes: 19 additions & 0 deletions net/http/http_network_transaction.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
#include "net/http/http_network_transaction.h"

#include "base/string_util.h"
#include "base/trace_event.h"
#include "net/base/client_socket_factory.h"
#include "net/base/host_resolver.h"
#include "net/base/load_flags.h"
Expand Down Expand Up @@ -254,66 +255,84 @@ int HttpNetworkTransaction::DoLoop(int result) {
switch (state) {
case STATE_RESOLVE_PROXY:
DCHECK(rv == OK);
TRACE_EVENT_BEGIN("http.resolve_proxy", request_, request_->url.spec());
rv = DoResolveProxy();
break;
case STATE_RESOLVE_PROXY_COMPLETE:
rv = DoResolveProxyComplete(rv);
TRACE_EVENT_END("http.resolve_proxy", request_, request_->url.spec());
break;
case STATE_INIT_CONNECTION:
DCHECK(rv == OK);
TRACE_EVENT_BEGIN("http.init_conn", request_, request_->url.spec());
rv = DoInitConnection();
break;
case STATE_INIT_CONNECTION_COMPLETE:
rv = DoInitConnectionComplete(rv);
TRACE_EVENT_END("http.init_conn", request_, request_->url.spec());
break;
case STATE_RESOLVE_HOST:
DCHECK(rv == OK);
TRACE_EVENT_BEGIN("http.resolve_host", request_, request_->url.spec());
rv = DoResolveHost();
break;
case STATE_RESOLVE_HOST_COMPLETE:
rv = DoResolveHostComplete(rv);
TRACE_EVENT_END("http.resolve_host", request_, request_->url.spec());
break;
case STATE_CONNECT:
DCHECK(rv == OK);
TRACE_EVENT_BEGIN("http.connect", request_, request_->url.spec());
rv = DoConnect();
break;
case STATE_CONNECT_COMPLETE:
rv = DoConnectComplete(rv);
TRACE_EVENT_END("http.connect", request_, request_->url.spec());
break;
case STATE_SSL_CONNECT_OVER_TUNNEL:
DCHECK(rv == OK);
TRACE_EVENT_BEGIN("http.ssl_tunnel", request_, request_->url.spec());
rv = DoSSLConnectOverTunnel();
break;
case STATE_SSL_CONNECT_OVER_TUNNEL_COMPLETE:
rv = DoSSLConnectOverTunnelComplete(rv);
TRACE_EVENT_END("http.ssl_tunnel", request_, request_->url.spec());
break;
case STATE_WRITE_HEADERS:
DCHECK(rv == OK);
TRACE_EVENT_BEGIN("http.write_headers", request_, request_->url.spec());
rv = DoWriteHeaders();
break;
case STATE_WRITE_HEADERS_COMPLETE:
rv = DoWriteHeadersComplete(rv);
TRACE_EVENT_END("http.write_headers", request_, request_->url.spec());
break;
case STATE_WRITE_BODY:
DCHECK(rv == OK);
TRACE_EVENT_BEGIN("http.write_body", request_, request_->url.spec());
rv = DoWriteBody();
break;
case STATE_WRITE_BODY_COMPLETE:
rv = DoWriteBodyComplete(rv);
TRACE_EVENT_END("http.write_body", request_, request_->url.spec());
break;
case STATE_READ_HEADERS:
DCHECK(rv == OK);
TRACE_EVENT_BEGIN("http.read_headers", request_, request_->url.spec());
rv = DoReadHeaders();
break;
case STATE_READ_HEADERS_COMPLETE:
rv = DoReadHeadersComplete(rv);
TRACE_EVENT_END("http.read_headers", request_, request_->url.spec());
break;
case STATE_READ_BODY:
DCHECK(rv == OK);
TRACE_EVENT_BEGIN("http.read_body", request_, request_->url.spec());
rv = DoReadBody();
break;
case STATE_READ_BODY_COMPLETE:
rv = DoReadBodyComplete(rv);
TRACE_EVENT_END("http.read_body", request_, request_->url.spec());
break;
default:
NOTREACHED() << "bad state";
Expand Down
Loading

0 comments on commit 113ab13

Please sign in to comment.