fixed pegging the cpu when we start missing bytes over the UART
diff --git a/aos/common/util/log_interval.h b/aos/common/util/log_interval.h
new file mode 100644
index 0000000..1e5c57b
--- /dev/null
+++ b/aos/common/util/log_interval.h
@@ -0,0 +1,82 @@
+#ifndef AOS_COMMON_UTIL_LOG_INTERVAL_H_
+#define AOS_COMMON_UTIL_LOG_INTERVAL_H_
+
+#include "aos/common/time.h"
+#include "aos/common/logging/logging.h"
+
+#include <string>
+
+namespace aos {
+namespace util {
+
+// A class to help with logging things that happen a lot only occasionally.
+//
+// Intended use {
+// static LogInterval interval(::aos::time::Time::InSeconds(0.2));
+//
+// if (WantToLog()) {
+// interval.WantToLog();
+// }
+// if (interval.ShouldLog()) {
+// LOG(DEBUG, "thingie happened! (%d times)\n", interval.Count());
+// }
+// }
+class LogInterval {
+ public:
+ constexpr LogInterval(const ::aos::time::Time &interval)
+ : count_(0), interval_(interval), last_done_(0, 0) {}
+
+ void WantToLog() {
+ if (count_ == 0) {
+ last_done_ = ::aos::time::Time::Now();
+ }
+ ++count_;
+ }
+ bool ShouldLog() {
+ const ::aos::time::Time now = ::aos::time::Time::Now();
+ const bool r = (now - last_done_) >= interval_;
+ if (r) {
+ last_done_ = now;
+ }
+ return r;
+ }
+ int Count() {
+ const int r = count_;
+ count_ = 0;
+ return r;
+ }
+
+ private:
+ int count_;
+ const ::aos::time::Time interval_;
+ ::aos::time::Time last_done_;
+};
+
+// This one is even easier to use. It always logs with a message "%s %d
+// times\n".
+class SimpleLogInterval {
+ public:
+ SimpleLogInterval(const ::aos::time::Time &interval, log_level level,
+ const ::std::string &message)
+ : interval_(interval), level_(level), message_(message) {}
+
+#define LOG_INTERVAL(simple_log) \
+ simple_log.Hit(LOG_SOURCENAME ": " STRINGIFY(__LINE__))
+ void Hit(const char *context) {
+ interval_.WantToLog();
+ if (interval_.ShouldLog()) {
+ log_do(level_, "%s: %.*s %d times\n", context, message_.size(),
+ message_.data(), interval_.Count());
+ }
+ }
+
+ private:
+ LogInterval interval_;
+ const log_level level_;
+ const ::std::string message_;
+};
+
+} // namespace util
+} // namespace aos
+
+#endif // AOS_COMMON_UTIL_LOG_INTERVAL_H_
diff --git a/aos/common/util/util.gyp b/aos/common/util/util.gyp
index 79275c0..98f1a3d 100644
--- a/aos/common/util/util.gyp
+++ b/aos/common/util/util.gyp
@@ -1,6 +1,21 @@
{
'targets': [
{
+ 'target_name': 'log_interval',
+ 'type': 'static_library',
+ 'sources': [
+ #'log_interval.h',
+ ],
+ 'dependencies': [
+ '<(AOS)/common/common.gyp:time',
+ '<(AOS)/build/aos.gyp:logging',
+ ],
+ 'export_dependent_settings': [
+ '<(AOS)/common/common.gyp:time',
+ '<(AOS)/build/aos.gyp:logging',
+ ],
+ },
+ {
'target_name': 'thread',
'type': 'static_library',
'sources': [
diff --git a/bbb_cape/src/bbb/bbb.gyp b/bbb_cape/src/bbb/bbb.gyp
index 25db9a5..8efe553 100644
--- a/bbb_cape/src/bbb/bbb.gyp
+++ b/bbb_cape/src/bbb/bbb.gyp
@@ -100,10 +100,12 @@
'<(DEPTH)/bbb_cape/src/cape/cape.gyp:cows',
'crc',
'byte_io',
+ '<(AOS)/common/util/util.gyp:log_interval',
],
'export_dependent_settings': [
'<(AOS)/build/aos.gyp:logging',
'<(AOS)/common/common.gyp:time',
+ '<(AOS)/common/util/util.gyp:log_interval',
],
},
{
@@ -161,12 +163,14 @@
'crc',
'sensor_generation',
'<(AOS)/linux_code/linux_code.gyp:configuration',
+ '<(AOS)/common/util/util.gyp:log_interval',
],
'export_dependent_settings': [
'packet_finder',
'data_struct',
'cape_manager',
'<(AOS)/common/common.gyp:time',
+ '<(AOS)/common/util/util.gyp:log_interval',
],
},
{
diff --git a/bbb_cape/src/bbb/packet_finder.cc b/bbb_cape/src/bbb/packet_finder.cc
index 747eaf8..5decec8 100644
--- a/bbb_cape/src/bbb/packet_finder.cc
+++ b/bbb_cape/src/bbb/packet_finder.cc
@@ -17,6 +17,15 @@
using ::aos::time::Time;
namespace bbb {
+namespace {
+
+// Enabling all of the debugging logs during normal operation on the BBB causes
+// it to use most of the CPU when it runs into trouble.
+const bool kDebugLogs = false;
+
+} // namespace
+
+constexpr ::aos::time::Time PacketFinder::kDebugLogInterval;
PacketFinder::PacketFinder(ByteReaderInterface *reader, size_t packet_size)
: reader_(reader),
@@ -102,7 +111,8 @@
reinterpret_cast<uint32_t *>(buf_), packet_size_,
reinterpret_cast<uint32_t *>(unstuffed_data_), packet_size_ - 4);
if (unstuffed == 0) {
- LOG(INFO, "invalid packet\n");
+ if (kDebugLogs) LOG(INFO, "invalid\n");
+ LOG_INTERVAL(invalid_packet_);
return false;
} else if (unstuffed != (packet_size_ - 4) / 4) {
LOG(WARNING, "packet is %" PRIu32 " words instead of %zu\n",
@@ -116,8 +126,11 @@
uint32_t calculated_checksum = cape::CalculateChecksum(
reinterpret_cast<uint8_t *>(unstuffed_data_), packet_size_ - 8);
if (sent_checksum != calculated_checksum) {
- LOG(INFO, "sent checksum: %" PRIx32 " vs calculated: %" PRIx32"\n",
- sent_checksum, calculated_checksum);
+ if (kDebugLogs) {
+ LOG(INFO, "sent %" PRIx32 " not %" PRIx32 "\n", sent_checksum,
+ calculated_checksum);
+ }
+ LOG_INTERVAL(bad_checksum_);
return false;
}
@@ -134,7 +147,7 @@
if (buf_[i] == 0) {
++zeros;
if (zeros == 4) {
- LOG(INFO, "found another packet start at %zd\n", i);
+ if (kDebugLogs) LOG(INFO, "start at %zd\n", i);
packet_bytes_ = packet_size_ - (i + 1);
memmove(buf_, buf_ + i + 1, packet_bytes_);
return false;
diff --git a/bbb_cape/src/bbb/packet_finder.h b/bbb_cape/src/bbb/packet_finder.h
index 80cb8b8..85281fb 100644
--- a/bbb_cape/src/bbb/packet_finder.h
+++ b/bbb_cape/src/bbb/packet_finder.h
@@ -7,6 +7,7 @@
#include "aos/common/logging/logging.h"
#include "aos/common/time.h"
#include "aos/common/macros.h"
+#include "aos/common/util/log_interval.h"
namespace bbb {
@@ -64,6 +65,14 @@
// Whether we've increased the priority of the IRQ yet.
bool irq_priority_increased_ = false;
+ typedef ::aos::util::SimpleLogInterval SimpleLogInterval;
+ static constexpr ::aos::time::Time kDebugLogInterval =
+ ::aos::time::Time::InSeconds(0.25);
+ SimpleLogInterval invalid_packet_ =
+ SimpleLogInterval(kDebugLogInterval, INFO, "invalid packet");
+ SimpleLogInterval bad_checksum_ =
+ SimpleLogInterval(kDebugLogInterval, INFO, "bad checksum");
+
DISALLOW_COPY_AND_ASSIGN(PacketFinder);
};
diff --git a/bbb_cape/src/bbb/sensor_reader.cc b/bbb_cape/src/bbb/sensor_reader.cc
index f9395c2..f7bb2ca 100644
--- a/bbb_cape/src/bbb/sensor_reader.cc
+++ b/bbb_cape/src/bbb/sensor_reader.cc
@@ -67,7 +67,7 @@
last_cape_timestamp_ = data->timestamp;
return data;
}
- LOG(WARNING, "receiving packet failed\n");
+ LOG_INTERVAL(receive_failed_);
}
}
diff --git a/bbb_cape/src/bbb/sensor_reader.h b/bbb_cape/src/bbb/sensor_reader.h
index 48c863a..ed2fbcf 100644
--- a/bbb_cape/src/bbb/sensor_reader.h
+++ b/bbb_cape/src/bbb/sensor_reader.h
@@ -7,6 +7,7 @@
#include "aos/common/time.h"
#include "aos/common/macros.h"
+#include "aos/common/util/log_interval.h"
#include "bbb/packet_finder.h"
#include "bbb/data_struct.h"
@@ -51,6 +52,10 @@
::aos::time::Time last_received_time_ = ::aos::time::Time::InSeconds(0);
uint64_t last_cape_timestamp_;
+ ::aos::util::SimpleLogInterval receive_failed_ =
+ ::aos::util::SimpleLogInterval(::aos::time::Time::InSeconds(0.2), WARNING,
+ "receive failed");
+
DISALLOW_COPY_AND_ASSIGN(SensorReader);
};