centralized printf formats and improved log_displayer performance
Before, log_displayer copied each message into the same structure that
gets put into queues etc so that it could be printed with the same
function. Now, it prints it directly, but using the same formats.
diff --git a/aos/build/queues/compiler.rb b/aos/build/queues/compiler.rb
index e4312fd..58b2bf1 100644
--- a/aos/build/queues/compiler.rb
+++ b/aos/build/queues/compiler.rb
@@ -88,6 +88,7 @@
cpp_tree.add_cc_include("aos/common/inttypes.h".inspect)
cpp_tree.add_cc_include("aos/common/queue_types.h".inspect)
cpp_tree.add_cc_include("aos/common/once.h".inspect)
+ cpp_tree.add_cc_include("aos/common/logging/logging_printf_formats.h".inspect)
cpp_tree.add_cc_using("::aos::to_network")
cpp_tree.add_cc_using("::aos::to_host")
diff --git a/aos/build/queues/objects/queue.rb b/aos/build/queues/objects/queue.rb
index b40ccb2..610bdf7 100644
--- a/aos/build/queues/objects/queue.rb
+++ b/aos/build/queues/objects/queue.rb
@@ -50,7 +50,7 @@
"int16_t" => "%\" PRId16 \"",
"int32_t" => "%\" PRId32 \"",
"int64_t" => "%\" PRId64 \"",
- "::aos::time::Time" => "%010\" PRId32 \".%05\" PRId32 \"s"}
+ "::aos::time::Time" => "\" AOS_TIME_FORMAT \""}
def toPrintFormat()
if(format = PrintFormat[@type])
return format;
diff --git a/aos/build/queues/output/message_dec.rb b/aos/build/queues/output/message_dec.rb
index a165359..40a2570 100644
--- a/aos/build/queues/output/message_dec.rb
+++ b/aos/build/queues/output/message_dec.rb
@@ -302,7 +302,7 @@
if (self.type == 'bool')
args.push("#{parent}#{self.name} ? 'T' : 'f'")
elsif (self.type == '::aos::time::Time')
- args.push("#{parent}#{self.name}.sec(), #{parent}#{self.name}.nsec()")
+ args.push("AOS_TIME_ARGS(#{parent}#{self.name}.sec(), #{parent}#{self.name}.nsec())")
else
args.push("#{parent}#{self.name}")
end
diff --git a/aos/build/queues/print_field.rb b/aos/build/queues/print_field.rb
index 2e70e15..c7b8530 100644
--- a/aos/build/queues/print_field.rb
+++ b/aos/build/queues/print_field.rb
@@ -17,6 +17,7 @@
#include "aos/common/byteorder.h"
#include "aos/common/time.h"
#include "aos/common/print_field_helpers.h"
+#include "aos/common/logging/logging_printf_formats.h"
namespace aos {
diff --git a/aos/common/logging/logging.h b/aos/common/logging/logging.h
index 673cc9a..114007b 100644
--- a/aos/common/logging/logging.h
+++ b/aos/common/logging/logging.h
@@ -8,6 +8,8 @@
#include <stdint.h>
#include <stdlib.h>
+#include "aos/common/macros.h"
+
#ifdef __cplusplus
extern "C" {
#endif
@@ -28,9 +30,6 @@
DECL_LEVELS;
#undef DECL_LEVEL
-#define STRINGIFY(x) TO_STRING(x)
-#define TO_STRING(x) #x
-
// Not static const size_t for C code.
#define LOG_MESSAGE_LEN 400
diff --git a/aos/common/logging/logging_impl.cc b/aos/common/logging/logging_impl.cc
index b74b69d..e7b0a5e 100644
--- a/aos/common/logging/logging_impl.cc
+++ b/aos/common/logging/logging_impl.cc
@@ -7,6 +7,7 @@
#include "aos/common/inttypes.h"
#include "aos/common/once.h"
#include "aos/common/queue_types.h"
+#include "aos/common/logging/logging_printf_formats.h"
namespace aos {
namespace logging {
@@ -138,17 +139,13 @@
}
void PrintMessage(FILE *output, const LogMessage &message) {
-#define NSECONDS_DIGITS 5
-#define BASE_FORMAT \
- "%.*s(%" PRId32 ")(%05" PRIu16 "): %-7s at %010" PRId32 \
- ".%0" STRINGIFY(NSECONDS_DIGITS) PRId32 "s: "
-#define BASE_ARGS \
- static_cast<int>(message.name_length), message.name, \
- static_cast<int32_t>(message.source), message.sequence, \
- log_str(message.level), message.seconds, (message.nseconds + 5000) / 10000
- switch (message.type) {
+#define BASE_ARGS \
+ AOS_LOGGING_BASE_ARGS( \
+ message.name_length, message.name, static_cast<int32_t>(message.source), \
+ message.sequence, message.level, message.seconds, message.nseconds)
+ switch (message.type) {
case LogMessage::Type::kString:
- fprintf(output, BASE_FORMAT "%.*s", BASE_ARGS,
+ fprintf(output, AOS_LOGGING_BASE_FORMAT "%.*s", BASE_ARGS,
static_cast<int>(message.message_length), message.message);
break;
case LogMessage::Type::kStruct: {
@@ -169,7 +166,7 @@
LOG(WARNING, "%zu extra bytes on message of type %s\n", input_length,
type_cache::Get(message.structure.type_id).name.c_str());
}
- fprintf(output, BASE_FORMAT "%.*s: %.*s\n", BASE_ARGS,
+ fprintf(output, AOS_LOGGING_BASE_FORMAT "%.*s: %.*s\n", BASE_ARGS,
static_cast<int>(message.structure.string_length),
message.structure.serialized,
static_cast<int>(sizeof(buffer) - output_length), buffer);
@@ -192,14 +189,12 @@
LOG(FATAL, "printing %dx%d matrix of type %" PRIu32 " failed\n",
message.matrix.rows, message.matrix.cols, message.matrix.type);
}
- fprintf(output, BASE_FORMAT "%.*s: %.*s\n", BASE_ARGS,
+ fprintf(output, AOS_LOGGING_BASE_FORMAT "%.*s: %.*s\n", BASE_ARGS,
static_cast<int>(message.matrix.string_length),
message.matrix.data,
static_cast<int>(sizeof(buffer) - output_length), buffer);
} break;
}
-#undef NSECONDS_DIGITS
-#undef BASE_FORMAT
#undef BASE_ARGS
}
diff --git a/aos/common/logging/logging_printf_formats.h b/aos/common/logging/logging_printf_formats.h
new file mode 100644
index 0000000..be186bc
--- /dev/null
+++ b/aos/common/logging/logging_printf_formats.h
@@ -0,0 +1,30 @@
+#ifndef AOS_COMMON_LOGGING_LOGGING_PRINTF_FORMATS_H_
+#define AOS_COMMON_LOGGING_LOGGING_PRINTF_FORMATS_H_
+
+#include "aos/common/macros.h"
+
+// This file has printf(3) formats and corresponding arguments for printing out
+// times and log messages.
+// They are all split out as macros because there are 2 things that want to
+// print using the same format: log_displayer and PrintMessage in
+// logging_impl.cc.
+
+#define AOS_TIME_FORMAT \
+ "%010" PRId32 ".%0" STRINGIFY(AOS_TIME_NSECONDS_DIGITS) PRId32 "s"
+#define AOS_TIME_ARGS(sec, nsec) \
+ sec, (nsec + (AOS_TIME_NSECONDS_DENOMINATOR / 2)) / \
+ AOS_TIME_NSECONDS_DENOMINATOR
+
+#define AOS_LOGGING_BASE_FORMAT \
+ "%.*s(%" PRId32 ")(%05" PRIu16 "): %-7s at " AOS_TIME_FORMAT ": "
+#define AOS_LOGGING_BASE_ARGS(name_length, name, source, sequence, level, sec, \
+ nsec) \
+ static_cast<int>(name_length), name, source, sequence, \
+ ::aos::logging::log_str(level), AOS_TIME_ARGS(sec, nsec)
+
+// These 2 define how many digits we use to print out the nseconds fields of
+// times. They have to stay matching.
+#define AOS_TIME_NSECONDS_DIGITS 5
+#define AOS_TIME_NSECONDS_DENOMINATOR 10000
+
+#endif // AOS_COMMON_LOGGING_LOGGING_PRINTF_FORMATS_H_
diff --git a/aos/common/macros.h b/aos/common/macros.h
index 2018b36..ba23fe4 100644
--- a/aos/common/macros.h
+++ b/aos/common/macros.h
@@ -22,4 +22,7 @@
#define UNUSED_VARIABLE
#endif
+#define STRINGIFY(x) TO_STRING(x)
+#define TO_STRING(x) #x
+
#endif // _AOS_COMMON_MACROS_H_
diff --git a/aos/linux_code/logging/binary_log_writer.cc b/aos/linux_code/logging/binary_log_writer.cc
index 7b9b6da..a14cd6c 100644
--- a/aos/linux_code/logging/binary_log_writer.cc
+++ b/aos/linux_code/logging/binary_log_writer.cc
@@ -186,22 +186,17 @@
case LogMessage::Type::kStruct: {
char *position = output_strings + msg->name_length;
- memcpy(position, &msg->structure.type_id,
- sizeof(msg->structure.type_id));
+ memcpy(position, &msg->structure.type_id, sizeof(msg->structure.type_id));
position += sizeof(msg->structure.type_id);
output->message_size += sizeof(msg->structure.type_id);
- uint32_t length = msg->structure.string_length;
+ const uint32_t length = msg->structure.string_length;
memcpy(position, &length, sizeof(length));
position += sizeof(length);
- memcpy(position, msg->structure.serialized, length);
- position += length;
+ memcpy(position, msg->structure.serialized, length + msg->message_length);
+ position += length + msg->message_length;
output->message_size += sizeof(length) + length;
- memcpy(position,
- msg->structure.serialized + msg->structure.string_length,
- msg->message_length);
-
output->type = LogFileMessageHeader::MessageType::kStruct;
} break;
case LogMessage::Type::kMatrix: {
diff --git a/aos/linux_code/logging/log_displayer.cc b/aos/linux_code/logging/log_displayer.cc
index 1cc5f43..cbf4891 100644
--- a/aos/linux_code/logging/log_displayer.cc
+++ b/aos/linux_code/logging/log_displayer.cc
@@ -10,8 +10,9 @@
#include <algorithm>
#include "aos/linux_code/logging/binary_log_file.h"
-#include "aos/common/logging/logging_impl.h"
#include "aos/common/queue_types.h"
+#include "aos/common/logging/logging_impl.h"
+#include "aos/common/logging/logging_printf_formats.h"
using ::aos::logging::linux_code::LogFileMessageHeader;
@@ -156,7 +157,6 @@
}
const LogFileMessageHeader *msg;
- ::aos::logging::LogMessage log_message;
do {
msg = accessor.ReadNextMessage(follow);
if (msg == NULL) {
@@ -192,84 +192,82 @@
}
}
- log_message.source = msg->source;
- log_message.sequence = msg->sequence;
- log_message.level = msg->level;
- log_message.seconds = msg->time_sec;
- log_message.nseconds = msg->time_nsec;
- memcpy(log_message.name, reinterpret_cast<const char *>(msg) + sizeof(*msg),
- ::std::min<size_t>(sizeof(log_message.name), msg->name_size));
- log_message.message_length = msg->message_size;
- log_message.name_length = msg->name_size;
-
+ const char *position =
+ reinterpret_cast<const char *>(msg + 1) + msg->name_size;
+#define BASE_ARGS \
+ AOS_LOGGING_BASE_ARGS( \
+ msg->name_size, reinterpret_cast<const char *>(msg + 1), msg->source, \
+ msg->sequence, msg->level, msg->time_sec, msg->time_nsec)
switch (msg->type) {
- case LogFileMessageHeader::MessageType::kStruct: {
- const char *position =
- reinterpret_cast<const char *>(msg + 1) + msg->name_size;
- memcpy(&log_message.structure.type_id, position,
- sizeof(log_message.structure.type_id));
- position += sizeof(log_message.structure.type_id);
-
- uint32_t length;
- memcpy(&length, position, sizeof(length));
- log_message.structure.string_length = length;
- position += sizeof(length);
- memcpy(log_message.structure.serialized, position, length);
- position += length;
-
- log_message.message_length -=
- sizeof(log_message.structure.type_id) + sizeof(uint32_t) +
- log_message.structure.string_length;
- memcpy(log_message.structure.serialized +
- log_message.structure.string_length,
- position, log_message.message_length);
-
- log_message.type = ::aos::logging::LogMessage::Type::kStruct;
+ case LogFileMessageHeader::MessageType::kString:
+ fprintf(stdout, AOS_LOGGING_BASE_FORMAT "%.*s", BASE_ARGS,
+ static_cast<int>(msg->message_size), position);
break;
- }
- case LogFileMessageHeader::MessageType::kMatrix: {
- const char *position =
- reinterpret_cast<const char *>(msg + 1) + msg->name_size;
- memcpy(&log_message.matrix.type, position,
- sizeof(log_message.matrix.type));
- position += sizeof(log_message.matrix.type);
+ case LogFileMessageHeader::MessageType::kStruct: {
+ uint32_t type_id;
+ memcpy(&type_id, position, sizeof(type_id));
+ position += sizeof(type_id);
- uint32_t length;
- memcpy(&length, position, sizeof(length));
- log_message.matrix.string_length = length;
- position += sizeof(length);
+ uint32_t string_length;
+ memcpy(&string_length, position, sizeof(string_length));
+ position += sizeof(string_length);
+
+ char buffer[2048];
+ size_t output_length = sizeof(buffer);
+ size_t input_length =
+ msg->message_size -
+ (sizeof(type_id) + sizeof(uint32_t) + string_length);
+ if (!PrintMessage(buffer, &output_length, position + string_length,
+ &input_length, ::aos::type_cache::Get(type_id))) {
+ LOG(FATAL, "printing message (%.*s) of type %s into %zu-byte buffer "
+ "failed\n",
+ static_cast<int>(string_length), position,
+ ::aos::type_cache::Get(type_id).name.c_str(), sizeof(buffer));
+ }
+ if (input_length > 0) {
+ LOG(WARNING, "%zu extra bytes on message of type %s\n",
+ input_length, ::aos::type_cache::Get(type_id).name.c_str());
+ }
+ fprintf(stdout, AOS_LOGGING_BASE_FORMAT "%.*s: %.*s\n", BASE_ARGS,
+ static_cast<int>(string_length), position,
+ static_cast<int>(sizeof(buffer) - output_length), buffer);
+ } break;
+ case LogFileMessageHeader::MessageType::kMatrix: {
+ uint32_t type;
+ memcpy(&type, position, sizeof(type));
+ position += sizeof(type);
+
+ uint32_t string_length;
+ memcpy(&string_length, position, sizeof(string_length));
+ position += sizeof(string_length);
uint16_t rows;
memcpy(&rows, position, sizeof(rows));
- log_message.matrix.rows = rows;
position += sizeof(rows);
uint16_t cols;
memcpy(&cols, position, sizeof(cols));
- log_message.matrix.cols = cols;
position += sizeof(cols);
- log_message.message_length -=
- sizeof(log_message.matrix.type) + sizeof(uint32_t) +
- sizeof(uint16_t) + sizeof(uint16_t) + length;
- CHECK_EQ(
- log_message.message_length,
- ::aos::MessageType::Sizeof(log_message.matrix.type) * rows * cols);
- memcpy(log_message.matrix.data, position,
- log_message.message_length + length);
-
- log_message.type = ::aos::logging::LogMessage::Type::kMatrix;
- break;
- } case LogFileMessageHeader::MessageType::kString:
- memcpy(
- log_message.message,
- reinterpret_cast<const char *>(msg) + sizeof(*msg) + msg->name_size,
- ::std::min<size_t>(sizeof(log_message.message), msg->message_size));
- log_message.type = ::aos::logging::LogMessage::Type::kString;
- break;
+ const size_t matrix_bytes =
+ msg->message_size -
+ (sizeof(type) + sizeof(uint32_t) + sizeof(uint16_t) +
+ sizeof(uint16_t) + string_length);
+ CHECK_EQ(matrix_bytes, ::aos::MessageType::Sizeof(type) * rows * cols);
+ char buffer[2048];
+ size_t output_length = sizeof(buffer);
+ if (!::aos::PrintMatrix(buffer, &output_length,
+ position + string_length, type, rows, cols)) {
+ LOG(FATAL, "printing %dx%d matrix of type %" PRIu32 " failed\n", rows,
+ cols, type);
+ }
+ fprintf(stdout, AOS_LOGGING_BASE_FORMAT "%.*s: %.*s\n", BASE_ARGS,
+ static_cast<int>(string_length), position,
+ static_cast<int>(sizeof(buffer) - output_length), buffer);
+ } break;
case LogFileMessageHeader::MessageType::kStructType:
LOG(FATAL, "shouldn't get here\n");
break;
- };
- ::aos::logging::internal::PrintMessage(stdout, log_message);
+ }
+#undef BASE_ARGS
} while (msg != NULL);
}