Reduce logging frequency for empty range tolarence

Summary: Pull Request resolved: pytorch#28704

Reviewed By: xianjiec

Differential Revision: D18138828

fbshipit-source-id: 4f3c376502cb6e30b931217702c4ca537c9eb644

Author: Xinyi Zhang

c10/util/Logging.h

@@ -47,6 +47,13 @@ C10_DECLARE_bool(caffe2_use_fatal_for_enforce);
 #define C10_LOG_FIRST_N(severity, n) LOG(severity)
 #endif
 
+// Same for LOG_EVERY_N
+#ifdef LOG_EVERY_N
+#define C10_LOG_EVERY_N(severity, n) LOG_EVERY_N(severity, n)
+#else
+#define C10_LOG_EVERY_N(severity, n) LOG(severity)
+#endif
+
 namespace c10 {
 
 using std::string;

caffe2/operators/gather_ranges_to_dense_op.cc

@@ -74,10 +74,13 @@ are sorted by the corresponding KEY.
         "empty ranges or mismatched ranges is alarming.")
     .Arg(
         "max_empty_ratio",
-        "An crital log is triggered when ratio of empty ranges exceeds this.")
+        "An error log is triggered when ratio of empty ranges exceeds this.")
     .Arg(
         "max_mismatched_ratio",
         "An error is raised when ratio of mismatched ranges exceeds this.")
+    .Arg(
+        "log_every_n",
+        "A log is recorded only after an error is triggered every n times.")
     .TensorInferenceFunction([](const OperatorDef& def,
                                 const vector<TensorShape>& in) {
       ArgumentHelper helper(def);

caffe2/operators/gather_ranges_to_dense_op.h

@@ -30,7 +30,12 @@ class GatherRangesToDenseOp final : public Operator<Context> {
             this->template GetSingleArgument<float>("max_empty_ratio", 0.9)),
         maxMismatchedRatio_(this->template GetSingleArgument<float>(
             "max_mismatched_ratio",
-            0.01)) {
+            0.01)),
+        // This number of log_every_n is intentionally set to a prime number
+        // so that the log will be trigger on all features eventually if
+        // multiple features are corrupt.
+        logEveryN_(
+            this->template GetSingleArgument<int64_t>("log_every_n", 4999)) {
     CAFFE_ENFORCE_GT(lengths_.size(), 0, "There has to be at least one length");
     for (auto length : lengths_) {
       CAFFE_ENFORCE_GT(length, 0, "Each length should be positive");
@@ -45,7 +50,7 @@ class GatherRangesToDenseOp final : public Operator<Context> {
   }
 
   ~GatherRangesToDenseOp() noexcept override {
-    if (totalRanges_ > 0) {
+    if (totalRanges_ > minObservation_) {
       LOG(INFO) << "In GatherRangesToDenseOp:\n"
                 << "  Lifetime empty ranges for each feature is "
                 << emptyRanges_ << ".\n"
@@ -173,13 +178,13 @@ class GatherRangesToDenseOp final : public Operator<Context> {
             ") which exceeds ",
             maxMismatchedRatio_);
         if (totalRanges_ * maxEmptyRatio_ <= emptyRanges_[j]) {
-          LOG(ERROR) << "Ratio of empty range for feature at index " << j
-                     << " is "
-                     << (static_cast<double>(emptyRanges_[j]) /
-                         static_cast<double>(totalRanges_))
-                     << " (" << emptyRanges_[j] << "/" << totalRanges_
-                     << ") which exceeds " << maxEmptyRatio_ << "\n"
-                     << this->getErrorMsg();
+          C10_LOG_EVERY_N(ERROR, logEveryN_)
+              << "Ratio of empty range for feature at index " << j << " is "
+              << (static_cast<double>(emptyRanges_[j]) /
+                  static_cast<double>(totalRanges_))
+              << " (" << emptyRanges_[j] << "/" << totalRanges_
+              << ") which exceeds " << maxEmptyRatio_ << "\n"
+              << this->getErrorMsg();
         }
       }
     }
@@ -200,6 +205,7 @@ class GatherRangesToDenseOp final : public Operator<Context> {
   int64_t minObservation_ = 0;
   float maxEmptyRatio_ = 0;
   float maxMismatchedRatio_ = 0;
+  int64_t logEveryN_ = 0;
 };
 
 } // namespace caffe2

caffe2/python/operator_test/gather_ranges_op_test.py

@@ -8,26 +8,30 @@
 
 
 def batched_boarders_and_data(
-        data_min_size=5, data_max_size=10,
-        examples_min_number=1, examples_max_number=4,
-        example_min_size=1, example_max_size=3,
-        dtype=np.float32, elements=None):
+    data_min_size=5,
+    data_max_size=10,
+    examples_min_number=1,
+    examples_max_number=4,
+    example_min_size=1,
+    example_max_size=3,
+    dtype=np.float32,
+    elements=None,
+):
     dims_ = st.tuples(
-        st.integers(min_value=data_min_size,
-                    max_value=data_max_size),
-        st.integers(min_value=examples_min_number,
-                    max_value=examples_max_number),
-        st.integers(min_value=example_min_size,
-                    max_value=example_max_size),
+        st.integers(min_value=data_min_size, max_value=data_max_size),
+        st.integers(min_value=examples_min_number, max_value=examples_max_number),
+        st.integers(min_value=example_min_size, max_value=example_max_size),
     )
     return dims_.flatmap(
         lambda dims: st.tuples(
             hu.arrays(
-                [dims[1], dims[2], 2], dtype=np.int32,
-                elements=st.integers(min_value=0, max_value=dims[0])
+                [dims[1], dims[2], 2],
+                dtype=np.int32,
+                elements=st.integers(min_value=0, max_value=dims[0]),
             ),
-            hu.arrays([dims[0]], dtype, elements)
-        ))
+            hu.arrays([dims[0]], dtype, elements),
+        )
+    )
 
 
 @st.composite
@@ -45,17 +49,19 @@ def _tensor_splits(draw):
         ranges[pair[0]][pair[1]] = (offset, lengths[pair[1]])
         offset += lengths[pair[1]]
 
-    data = draw(st.lists(
-        st.floats(min_value=-1.0, max_value=1.0),
-        min_size=offset,
-        max_size=offset
-    ))
+    data = draw(
+        st.lists(
+            st.floats(min_value=-1.0, max_value=1.0), min_size=offset, max_size=offset
+        )
+    )
 
     key = draw(st.permutations(range(offset)))
 
     return (
-        np.array(data).astype(np.float32), np.array(ranges),
-        np.array(lengths), np.array(key).astype(np.int64)
+        np.array(data).astype(np.float32),
+        np.array(ranges),
+        np.array(lengths),
+        np.array(key).astype(np.int64),
     )
 
 
@@ -107,7 +113,7 @@ def gather_ranges(data, ranges):
         length = 0
         for range in example_ranges:
             assert len(range) == 2
-            output.extend(data[range[0]:range[0] + range[1]])
+            output.extend(data[range[0] : range[0] + range[1]])
             length += range[1]
         lengths.append(length)
     return output, lengths
@@ -128,7 +134,7 @@ def gather_ranges_to_dense(data, ranges, lengths):
                 out.append([0] * lengths[i])
             else:
                 assert length == lengths[i]
-                out.append(data[start:start + length])
+                out.append(data[start : start + length])
         outputs.append(np.array(out))
     return outputs
 
@@ -149,8 +155,8 @@ def gather_ranges_to_dense_with_key(data, ranges, key, lengths):
             else:
                 assert length == lengths[i]
                 key_data_list = zip(
-                    key[start:start + length],
-                    data[start:start + length])
+                    key[start : start + length], data[start : start + length]
+                )
                 sorted_key_data_list = sorted(key_data_list, key=lambda x: x[0])
                 sorted_data = [d for (k, d) in sorted_key_data_list]
                 out.append(sorted_data)
@@ -159,8 +165,7 @@ def gather_ranges_to_dense_with_key(data, ranges, key, lengths):
 
 
 class TestGatherRanges(serial.SerializedTestCase):
-    @serial.given(
-        boarders_and_data=batched_boarders_and_data(), **hu.gcs_cpu_only)
+    @serial.given(boarders_and_data=batched_boarders_and_data(), **hu.gcs_cpu_only)
     def test_gather_ranges(self, boarders_and_data, gc, dc):
         boarders, data = boarders_and_data
 
@@ -173,9 +178,9 @@ def boarders_to_range(boarders):
 
         self.assertReferenceChecks(
             device_option=gc,
-            op=core.CreateOperator("GatherRanges",
-                                   ["data", "ranges"],
-                                   ["output", "lengths"]),
+            op=core.CreateOperator(
+                "GatherRanges", ["data", "ranges"], ["output", "lengths"]
+            ),
             inputs=[data, ranges],
             reference=gather_ranges,
         )
@@ -188,12 +193,12 @@ def test_gather_ranges_split(self, tensor_splits, gc, dc):
             device_option=gc,
             op=core.CreateOperator(
                 "GatherRangesToDense",
-                ['data', 'ranges'],
-                ['X_{}'.format(i) for i in range(len(lengths))],
-                lengths=lengths
+                ["data", "ranges"],
+                ["X_{}".format(i) for i in range(len(lengths))],
+                lengths=lengths,
             ),
             inputs=[data, ranges, lengths],
-            reference=gather_ranges_to_dense
+            reference=gather_ranges_to_dense,
         )
 
     @given(tensor_splits=_tensor_splits(), **hu.gcs_cpu_only)
@@ -204,24 +209,20 @@ def test_gather_ranges_with_key_split(self, tensor_splits, gc, dc):
             device_option=gc,
             op=core.CreateOperator(
                 "GatherRangesToDense",
-                ['data', 'ranges', 'key'],
-                ['X_{}'.format(i) for i in range(len(lengths))],
-                lengths=lengths
+                ["data", "ranges", "key"],
+                ["X_{}".format(i) for i in range(len(lengths))],
+                lengths=lengths,
             ),
             inputs=[data, ranges, key, lengths],
-            reference=gather_ranges_to_dense_with_key
+            reference=gather_ranges_to_dense_with_key,
         )
 
     def test_shape_and_type_inference(self):
         with hu.temp_workspace("shape_type_inf_int32"):
-            net = core.Net('test_net')
-            net.ConstantFill(
-                [], "ranges", shape=[3, 5, 2], dtype=core.DataType.INT32,
-            )
-            net.ConstantFill(
-                [], "values", shape=[64], dtype=core.DataType.INT64,
-            )
-            net.GatherRanges(['values', 'ranges'], ['values_output', 'lengths_output'])
+            net = core.Net("test_net")
+            net.ConstantFill([], "ranges", shape=[3, 5, 2], dtype=core.DataType.INT32)
+            net.ConstantFill([], "values", shape=[64], dtype=core.DataType.INT64)
+            net.GatherRanges(["values", "ranges"], ["values_output", "lengths_output"])
             (shapes, types) = workspace.InferShapesAndTypes([net], {})
 
             self.assertEqual(shapes["values_output"], [64])
@@ -238,7 +239,10 @@ def test_empty_range_check(self, tensor_splits, gc, dc):
         workspace.FeedBlob("key", key)
 
         def getOpWithThreshold(
-            min_observation=2, max_empty_ratio=0.3, max_mismatched_ratio=0.6
+            min_observation=2,
+            max_empty_ratio=0.3,
+            max_mismatched_ratio=0.6,
+            log_every_n=1,
         ):
             return core.CreateOperator(
                 "GatherRangesToDense",
@@ -248,13 +252,19 @@ def getOpWithThreshold(
                 min_observation=min_observation,
                 max_empty_ratio=max_empty_ratio,
                 max_mismatched_ratio=max_mismatched_ratio,
+                log_every_n=log_every_n,
             )
 
         workspace.RunOperatorOnce(getOpWithThreshold())
 
-        # A critical log should be triggered by this setting.
+        # An error log should be triggered by each feature in this setting.
         workspace.RunOperatorOnce(getOpWithThreshold(max_empty_ratio=0.2))
 
+        # Error logs should be triggered only half the time.
+        workspace.RunOperatorOnce(
+            getOpWithThreshold(max_empty_ratio=0.2, log_every_n=2)
+        )
+
         workspace.RunOperatorOnce(
             getOpWithThreshold(
                 max_empty_ratio=0.2, max_mismatched_ratio=0.4, min_observation=5