blob: 28de280a9d954ebf6c1cb54cd416e057ab0123fc [file] [log] [blame]
/*
* Copyright (c) 2012 The WebRTC project authors. All Rights Reserved.
*
* Use of this source code is governed by a BSD-style license
* that can be found in the LICENSE file in the root of the source
* tree. An additional intellectual property rights grant can be found
* in the file PATENTS. All contributing project authors may
* be found in the AUTHORS file in the root of the source tree.
*/
#include "webrtc/system_wrappers/source/trace_impl.h"
#include <assert.h>
#include <stdarg.h>
#include <stdio.h>
#include <string.h>
#ifdef _WIN32
#include "webrtc/system_wrappers/source/trace_win.h"
#else
#include "webrtc/system_wrappers/source/trace_posix.h"
#endif // _WIN32
#include "webrtc/system_wrappers/interface/sleep.h"
#define KEY_LEN_CHARS 31
#ifdef _WIN32
#pragma warning(disable:4355)
#endif // _WIN32
namespace webrtc {
const int Trace::kBoilerplateLength = 71;
const int Trace::kTimestampPosition = 13;
const int Trace::kTimestampLength = 12;
uint32_t Trace::level_filter_ = kTraceDefault;
// Construct On First Use idiom. Avoids "static initialization order fiasco".
TraceImpl* TraceImpl::StaticInstance(CountOperation count_operation,
const TraceLevel level) {
// Sanities to avoid taking lock unless absolutely necessary (for
// performance reasons). count_operation == kAddRefNoCreate implies that a
// message will be written to file.
if ((level != kTraceAll) && (count_operation == kAddRefNoCreate)) {
if (!(level & level_filter())) {
return NULL;
}
}
TraceImpl* impl =
GetStaticInstance<TraceImpl>(count_operation);
return impl;
}
TraceImpl* TraceImpl::GetTrace(const TraceLevel level) {
return StaticInstance(kAddRefNoCreate, level);
}
TraceImpl* TraceImpl::CreateInstance() {
#if defined(_WIN32)
return new TraceWindows();
#else
return new TracePosix();
#endif
}
TraceImpl::TraceImpl()
: critsect_interface_(CriticalSectionWrapper::CreateCriticalSection()),
callback_(NULL),
row_count_text_(0),
file_count_text_(0),
trace_file_(*FileWrapper::Create()),
thread_(*ThreadWrapper::CreateThread(TraceImpl::Run, this,
kHighestPriority, "Trace")),
event_(*EventWrapper::Create()),
critsect_array_(CriticalSectionWrapper::CreateCriticalSection()),
next_free_idx_(),
level_(),
length_(),
message_queue_(),
active_queue_(0) {
next_free_idx_[0] = 0;
next_free_idx_[1] = 0;
unsigned int tid = 0;
thread_.Start(tid);
for (int m = 0; m < WEBRTC_TRACE_NUM_ARRAY; ++m) {
for (int n = 0; n < WEBRTC_TRACE_MAX_QUEUE; ++n) {
message_queue_[m][n] = new
char[WEBRTC_TRACE_MAX_MESSAGE_SIZE];
}
}
}
bool TraceImpl::StopThread() {
// Release the worker thread so that it can flush any lingering messages.
event_.Set();
// Allow 10 ms for pending messages to be flushed out.
// TODO(hellner): why not use condition variables to do this? Or let the
// worker thread die and let this thread flush remaining
// messages?
SleepMs(10);
// Make sure the thread finishes as quickly as possible (instead of having
// to wait for the timeout).
event_.Set();
bool stopped = thread_.Stop();
CriticalSectionScoped lock(critsect_interface_);
trace_file_.Flush();
trace_file_.CloseFile();
return stopped;
}
TraceImpl::~TraceImpl() {
StopThread();
delete &event_;
delete &trace_file_;
delete &thread_;
delete critsect_interface_;
delete critsect_array_;
for (int m = 0; m < WEBRTC_TRACE_NUM_ARRAY; ++m) {
for (int n = 0; n < WEBRTC_TRACE_MAX_QUEUE; ++n) {
delete [] message_queue_[m][n];
}
}
}
int32_t TraceImpl::AddThreadId(char* trace_message) const {
uint32_t thread_id = ThreadWrapper::GetThreadId();
// Messages is 12 characters.
return sprintf(trace_message, "%10u; ", thread_id);
}
int32_t TraceImpl::AddLevel(char* sz_message, const TraceLevel level) const {
const int kMessageLength = 12;
switch (level) {
case kTraceTerseInfo:
// Add the appropriate amount of whitespace.
memset(sz_message, ' ', kMessageLength);
sz_message[kMessageLength] = '\0';
break;
case kTraceStateInfo:
sprintf(sz_message, "STATEINFO ; ");
break;
case kTraceWarning:
sprintf(sz_message, "WARNING ; ");
break;
case kTraceError:
sprintf(sz_message, "ERROR ; ");
break;
case kTraceCritical:
sprintf(sz_message, "CRITICAL ; ");
break;
case kTraceInfo:
sprintf(sz_message, "DEBUGINFO ; ");
break;
case kTraceModuleCall:
sprintf(sz_message, "MODULECALL; ");
break;
case kTraceMemory:
sprintf(sz_message, "MEMORY ; ");
break;
case kTraceTimer:
sprintf(sz_message, "TIMER ; ");
break;
case kTraceStream:
sprintf(sz_message, "STREAM ; ");
break;
case kTraceApiCall:
sprintf(sz_message, "APICALL ; ");
break;
case kTraceDebug:
sprintf(sz_message, "DEBUG ; ");
break;
default:
assert(false);
return 0;
}
// All messages are 12 characters.
return kMessageLength;
}
int32_t TraceImpl::AddModuleAndId(char* trace_message,
const TraceModule module,
const int32_t id) const {
// Use long int to prevent problems with different definitions of
// int32_t.
// TODO(hellner): is this actually a problem? If so, it should be better to
// clean up int32_t
const long int idl = id;
const int kMessageLength = 25;
if (idl != -1) {
const unsigned long int id_engine = id >> 16;
const unsigned long int id_channel = id & 0xffff;
switch (module) {
case kTraceUndefined:
// Add the appropriate amount of whitespace.
memset(trace_message, ' ', kMessageLength);
trace_message[kMessageLength] = '\0';
break;
case kTraceVoice:
sprintf(trace_message, " VOICE:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceVideo:
sprintf(trace_message, " VIDEO:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceUtility:
sprintf(trace_message, " UTILITY:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceRtpRtcp:
sprintf(trace_message, " RTP/RTCP:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceTransport:
sprintf(trace_message, " TRANSPORT:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceAudioCoding:
sprintf(trace_message, "AUDIO CODING:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceSrtp:
sprintf(trace_message, " SRTP:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceAudioMixerServer:
sprintf(trace_message, " AUDIO MIX/S:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceAudioMixerClient:
sprintf(trace_message, " AUDIO MIX/C:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceVideoCoding:
sprintf(trace_message, "VIDEO CODING:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceVideoMixer:
// Print sleep time and API call
sprintf(trace_message, " VIDEO MIX:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceFile:
sprintf(trace_message, " FILE:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceAudioProcessing:
sprintf(trace_message, " AUDIO PROC:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceAudioDevice:
sprintf(trace_message, "AUDIO DEVICE:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceVideoRenderer:
sprintf(trace_message, "VIDEO RENDER:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceVideoCapture:
sprintf(trace_message, "VIDEO CAPTUR:%5ld %5ld;", id_engine,
id_channel);
break;
case kTraceRemoteBitrateEstimator:
sprintf(trace_message, " BWE RBE:%5ld %5ld;", id_engine,
id_channel);
break;
}
} else {
switch (module) {
case kTraceUndefined:
// Add the appropriate amount of whitespace.
memset(trace_message, ' ', kMessageLength);
trace_message[kMessageLength] = '\0';
break;
case kTraceVoice:
sprintf(trace_message, " VOICE:%11ld;", idl);
break;
case kTraceVideo:
sprintf(trace_message, " VIDEO:%11ld;", idl);
break;
case kTraceUtility:
sprintf(trace_message, " UTILITY:%11ld;", idl);
break;
case kTraceRtpRtcp:
sprintf(trace_message, " RTP/RTCP:%11ld;", idl);
break;
case kTraceTransport:
sprintf(trace_message, " TRANSPORT:%11ld;", idl);
break;
case kTraceAudioCoding:
sprintf(trace_message, "AUDIO CODING:%11ld;", idl);
break;
case kTraceSrtp:
sprintf(trace_message, " SRTP:%11ld;", idl);
break;
case kTraceAudioMixerServer:
sprintf(trace_message, " AUDIO MIX/S:%11ld;", idl);
break;
case kTraceAudioMixerClient:
sprintf(trace_message, " AUDIO MIX/C:%11ld;", idl);
break;
case kTraceVideoCoding:
sprintf(trace_message, "VIDEO CODING:%11ld;", idl);
break;
case kTraceVideoMixer:
sprintf(trace_message, " VIDEO MIX:%11ld;", idl);
break;
case kTraceFile:
sprintf(trace_message, " FILE:%11ld;", idl);
break;
case kTraceAudioProcessing:
sprintf(trace_message, " AUDIO PROC:%11ld;", idl);
break;
case kTraceAudioDevice:
sprintf(trace_message, "AUDIO DEVICE:%11ld;", idl);
break;
case kTraceVideoRenderer:
sprintf(trace_message, "VIDEO RENDER:%11ld;", idl);
break;
case kTraceVideoCapture:
sprintf(trace_message, "VIDEO CAPTUR:%11ld;", idl);
break;
case kTraceRemoteBitrateEstimator:
sprintf(trace_message, " BWE RBE:%11ld;", idl);
break;
}
}
return kMessageLength;
}
int32_t TraceImpl::SetTraceFileImpl(const char* file_name_utf8,
const bool add_file_counter) {
CriticalSectionScoped lock(critsect_interface_);
trace_file_.Flush();
trace_file_.CloseFile();
if (file_name_utf8) {
if (add_file_counter) {
file_count_text_ = 1;
char file_name_with_counter_utf8[FileWrapper::kMaxFileNameSize];
CreateFileName(file_name_utf8, file_name_with_counter_utf8,
file_count_text_);
if (trace_file_.OpenFile(file_name_with_counter_utf8, false, false,
true) == -1) {
return -1;
}
} else {
file_count_text_ = 0;
if (trace_file_.OpenFile(file_name_utf8, false, false, true) == -1) {
return -1;
}
}
}
row_count_text_ = 0;
return 0;
}
int32_t TraceImpl::TraceFileImpl(
char file_name_utf8[FileWrapper::kMaxFileNameSize]) {
CriticalSectionScoped lock(critsect_interface_);
return trace_file_.FileName(file_name_utf8, FileWrapper::kMaxFileNameSize);
}
int32_t TraceImpl::SetTraceCallbackImpl(TraceCallback* callback) {
CriticalSectionScoped lock(critsect_interface_);
callback_ = callback;
return 0;
}
int32_t TraceImpl::AddMessage(
char* trace_message,
const char msg[WEBRTC_TRACE_MAX_MESSAGE_SIZE],
const uint16_t written_so_far) const {
int length = 0;
if (written_so_far >= WEBRTC_TRACE_MAX_MESSAGE_SIZE) {
return -1;
}
// - 2 to leave room for newline and NULL termination.
#ifdef _WIN32
length = _snprintf(trace_message,
WEBRTC_TRACE_MAX_MESSAGE_SIZE - written_so_far - 2,
"%s", msg);
if (length < 0) {
length = WEBRTC_TRACE_MAX_MESSAGE_SIZE - written_so_far - 2;
trace_message[length] = 0;
}
#else
length = snprintf(trace_message,
WEBRTC_TRACE_MAX_MESSAGE_SIZE - written_so_far - 2,
"%s", msg);
if (length < 0 ||
length > WEBRTC_TRACE_MAX_MESSAGE_SIZE - written_so_far - 2) {
length = WEBRTC_TRACE_MAX_MESSAGE_SIZE - written_so_far - 2;
trace_message[length] = 0;
}
#endif
// Length with NULL termination.
return length + 1;
}
void TraceImpl::AddMessageToList(
const char trace_message[WEBRTC_TRACE_MAX_MESSAGE_SIZE],
const uint16_t length,
const TraceLevel level) {
// NOTE(andresp): Enabled externally.
#ifdef WEBRTC_DIRECT_TRACE
if (callback_) {
callback_->Print(level, trace_message, length);
}
return;
#endif
CriticalSectionScoped lock(critsect_array_);
if (next_free_idx_[active_queue_] >= WEBRTC_TRACE_MAX_QUEUE) {
if (!trace_file_.Open() && !callback_) {
// Keep at least the last 1/4 of old messages when not logging.
// TODO(hellner): isn't this redundant. The user will make it known
// when to start logging. Why keep messages before
// that?
for (int n = 0; n < WEBRTC_TRACE_MAX_QUEUE / 4; ++n) {
const int last_quarter_offset = (3 * WEBRTC_TRACE_MAX_QUEUE / 4);
memcpy(message_queue_[active_queue_][n],
message_queue_[active_queue_][n + last_quarter_offset],
WEBRTC_TRACE_MAX_MESSAGE_SIZE);
}
next_free_idx_[active_queue_] = WEBRTC_TRACE_MAX_QUEUE / 4;
} else {
// More messages are being written than there is room for in the
// buffer. Drop any new messages.
// TODO(hellner): its probably better to drop old messages instead
// of new ones. One step further: if this happens
// it's due to writing faster than what can be
// processed. Maybe modify the filter at this point.
// E.g. turn of STREAM.
return;
}
}
uint16_t idx = next_free_idx_[active_queue_];
next_free_idx_[active_queue_]++;
level_[active_queue_][idx] = level;
length_[active_queue_][idx] = length;
memcpy(message_queue_[active_queue_][idx], trace_message, length);
if (next_free_idx_[active_queue_] == WEBRTC_TRACE_MAX_QUEUE - 1) {
// Logging more messages than can be worked off. Log a warning.
const char warning_msg[] = "WARNING MISSING TRACE MESSAGES\n";
level_[active_queue_][next_free_idx_[active_queue_]] = kTraceWarning;
length_[active_queue_][next_free_idx_[active_queue_]] = strlen(warning_msg);
memcpy(message_queue_[active_queue_][next_free_idx_[active_queue_]],
warning_msg, strlen(warning_msg));
next_free_idx_[active_queue_]++;
}
}
bool TraceImpl::Run(void* obj) {
return static_cast<TraceImpl*>(obj)->Process();
}
bool TraceImpl::Process() {
if (event_.Wait(1000) == kEventSignaled) {
// This slightly odd construction is to avoid locking |critsect_interface_|
// while calling WriteToFile() since it's locked inside the function.
critsect_interface_->Enter();
bool write_to_file = trace_file_.Open() || callback_;
critsect_interface_->Leave();
if (write_to_file) {
WriteToFile();
}
} else {
CriticalSectionScoped lock(critsect_interface_);
trace_file_.Flush();
}
return true;
}
void TraceImpl::WriteToFile() {
uint8_t local_queue_active = 0;
uint16_t local_next_free_idx = 0;
// There are two buffers. One for reading (for writing to file) and one for
// writing (for storing new messages). Let new messages be posted to the
// unused buffer so that the current buffer can be flushed safely.
{
CriticalSectionScoped lock(critsect_array_);
local_next_free_idx = next_free_idx_[active_queue_];
next_free_idx_[active_queue_] = 0;
local_queue_active = active_queue_;
if (active_queue_ == 0) {
active_queue_ = 1;
} else {
active_queue_ = 0;
}
}
if (local_next_free_idx == 0) {
return;
}
CriticalSectionScoped lock(critsect_interface_);
for (uint16_t idx = 0; idx < local_next_free_idx; ++idx) {
TraceLevel local_level = level_[local_queue_active][idx];
if (callback_) {
callback_->Print(local_level, message_queue_[local_queue_active][idx],
length_[local_queue_active][idx]);
}
if (trace_file_.Open()) {
if (row_count_text_ > WEBRTC_TRACE_MAX_FILE_SIZE) {
// wrap file
row_count_text_ = 0;
trace_file_.Flush();
if (file_count_text_ == 0) {
trace_file_.Rewind();
} else {
char old_file_name[FileWrapper::kMaxFileNameSize];
char new_file_name[FileWrapper::kMaxFileNameSize];
// get current name
trace_file_.FileName(old_file_name,
FileWrapper::kMaxFileNameSize);
trace_file_.CloseFile();
file_count_text_++;
UpdateFileName(old_file_name, new_file_name, file_count_text_);
if (trace_file_.OpenFile(new_file_name, false, false,
true) == -1) {
return;
}
}
}
if (row_count_text_ == 0) {
char message[WEBRTC_TRACE_MAX_MESSAGE_SIZE + 1];
int32_t length = AddDateTimeInfo(message);
if (length != -1) {
message[length] = 0;
message[length - 1] = '\n';
trace_file_.Write(message, length);
row_count_text_++;
}
}
uint16_t length = length_[local_queue_active][idx];
message_queue_[local_queue_active][idx][length] = 0;
message_queue_[local_queue_active][idx][length - 1] = '\n';
trace_file_.Write(message_queue_[local_queue_active][idx], length);
row_count_text_++;
}
}
}
void TraceImpl::AddImpl(const TraceLevel level, const TraceModule module,
const int32_t id,
const char msg[WEBRTC_TRACE_MAX_MESSAGE_SIZE]) {
if (TraceCheck(level)) {
char trace_message[WEBRTC_TRACE_MAX_MESSAGE_SIZE];
char* message_ptr = trace_message;
int32_t len = 0;
int32_t ack_len = 0;
len = AddLevel(message_ptr, level);
if (len == -1) {
return;
}
message_ptr += len;
ack_len += len;
len = AddTime(message_ptr, level);
if (len == -1) {
return;
}
message_ptr += len;
ack_len += len;
len = AddModuleAndId(message_ptr, module, id);
if (len == -1) {
return;
}
message_ptr += len;
ack_len += len;
len = AddThreadId(message_ptr);
if (len < 0) {
return;
}
message_ptr += len;
ack_len += len;
len = AddMessage(message_ptr, msg, (uint16_t)ack_len);
if (len == -1) {
return;
}
ack_len += len;
AddMessageToList(trace_message, (uint16_t)ack_len, level);
// Make sure that messages are written as soon as possible.
event_.Set();
}
}
bool TraceImpl::TraceCheck(const TraceLevel level) const {
return (level & level_filter()) ? true : false;
}
bool TraceImpl::UpdateFileName(
const char file_name_utf8[FileWrapper::kMaxFileNameSize],
char file_name_with_counter_utf8[FileWrapper::kMaxFileNameSize],
const uint32_t new_count) const {
int32_t length = (int32_t)strlen(file_name_utf8);
if (length < 0) {
return false;
}
int32_t length_without_file_ending = length - 1;
while (length_without_file_ending > 0) {
if (file_name_utf8[length_without_file_ending] == '.') {
break;
} else {
length_without_file_ending--;
}
}
if (length_without_file_ending == 0) {
length_without_file_ending = length;
}
int32_t length_to_ = length_without_file_ending - 1;
while (length_to_ > 0) {
if (file_name_utf8[length_to_] == '_') {
break;
} else {
length_to_--;
}
}
memcpy(file_name_with_counter_utf8, file_name_utf8, length_to_);
sprintf(file_name_with_counter_utf8 + length_to_, "_%lu%s",
static_cast<long unsigned int>(new_count),
file_name_utf8 + length_without_file_ending);
return true;
}
bool TraceImpl::CreateFileName(
const char file_name_utf8[FileWrapper::kMaxFileNameSize],
char file_name_with_counter_utf8[FileWrapper::kMaxFileNameSize],
const uint32_t new_count) const {
int32_t length = (int32_t)strlen(file_name_utf8);
if (length < 0) {
return false;
}
int32_t length_without_file_ending = length - 1;
while (length_without_file_ending > 0) {
if (file_name_utf8[length_without_file_ending] == '.') {
break;
} else {
length_without_file_ending--;
}
}
if (length_without_file_ending == 0) {
length_without_file_ending = length;
}
memcpy(file_name_with_counter_utf8, file_name_utf8,
length_without_file_ending);
sprintf(file_name_with_counter_utf8 + length_without_file_ending, "_%lu%s",
static_cast<long unsigned int>(new_count),
file_name_utf8 + length_without_file_ending);
return true;
}
void Trace::CreateTrace() {
TraceImpl::StaticInstance(kAddRef);
}
void Trace::ReturnTrace() {
TraceImpl::StaticInstance(kRelease);
}
int32_t Trace::TraceFile(char file_name[FileWrapper::kMaxFileNameSize]) {
TraceImpl* trace = TraceImpl::GetTrace();
if (trace) {
int ret_val = trace->TraceFileImpl(file_name);
ReturnTrace();
return ret_val;
}
return -1;
}
int32_t Trace::SetTraceFile(const char* file_name,
const bool add_file_counter) {
TraceImpl* trace = TraceImpl::GetTrace();
if (trace) {
int ret_val = trace->SetTraceFileImpl(file_name, add_file_counter);
ReturnTrace();
return ret_val;
}
return -1;
}
int32_t Trace::SetTraceCallback(TraceCallback* callback) {
TraceImpl* trace = TraceImpl::GetTrace();
if (trace) {
int ret_val = trace->SetTraceCallbackImpl(callback);
ReturnTrace();
return ret_val;
}
return -1;
}
void Trace::Add(const TraceLevel level, const TraceModule module,
const int32_t id, const char* msg, ...) {
TraceImpl* trace = TraceImpl::GetTrace(level);
if (trace) {
if (trace->TraceCheck(level)) {
char temp_buff[WEBRTC_TRACE_MAX_MESSAGE_SIZE];
char* buff = 0;
if (msg) {
va_list args;
va_start(args, msg);
#ifdef _WIN32
_vsnprintf(temp_buff, WEBRTC_TRACE_MAX_MESSAGE_SIZE - 1, msg, args);
#else
vsnprintf(temp_buff, WEBRTC_TRACE_MAX_MESSAGE_SIZE - 1, msg, args);
#endif
va_end(args);
buff = temp_buff;
}
trace->AddImpl(level, module, id, buff);
}
ReturnTrace();
}
}
} // namespace webrtc