Xla: xm.RateTracker() metrics seem inaccurate

[jysohn23]

While investigating and experimenting on performance improvements for models, I was seeing very weird example/sec rate metrics w.r.t. wall time. Whereas the rate increases, the wall-time does not decrease and instead increases, which is the exact opposite as expected.

For example these are the 2 different runs (sorted by core):

1. Taking [xla:1](100) -> md5-e82895d30622d892ecf758d83c95332bxla:1](120): Rate = ~300 img/sec, WallTime = 15 sec

[xla:1](100) Loss=0.00071 Rate=311.46 Time=2019-08-01 21:24:30.245111
[xla:1](120) Loss=0.00081 Rate=286.73 Time=2019-08-01 21:24:45.246750
[xla:2](100) Loss=0.00071 Rate=308.83 Time=2019-08-01 21:24:30.245550
[xla:2](120) Loss=0.00081 Rate=278.57 Time=2019-08-01 21:24:45.309707
[xla:3](100) Loss=0.00071 Rate=331.48 Time=2019-08-01 21:24:30.182048
[xla:3](120) Loss=0.00081 Rate=284.29 Time=2019-08-01 21:24:45.321068
[xla:4](100) Loss=0.00071 Rate=310.44 Time=2019-08-01 21:24:30.245271
[xla:4](120) Loss=0.00081 Rate=283.65 Time=2019-08-01 21:24:45.309553
[xla:5](100) Loss=0.00071 Rate=305.80 Time=2019-08-01 21:24:30.245647
[xla:5](120) Loss=0.00081 Rate=284.84 Time=2019-08-01 21:24:45.241928
[xla:6](100) Loss=0.00071 Rate=304.85 Time=2019-08-01 21:24:30.266800
[xla:6](120) Loss=0.00081 Rate=282.30 Time=2019-08-01 21:24:45.246627
[xla:7](100) Loss=0.00071 Rate=300.93 Time=2019-08-01 21:24:30.267052
[xla:7](120) Loss=0.00081 Rate=287.01 Time=2019-08-01 21:24:45.309854
[xla:8](100) Loss=0.00071 Rate=313.21 Time=2019-08-01 21:24:30.266670
[xla:8](120) Loss=0.00081 Rate=284.25 Time=2019-08-01 21:24:45.309947

1. Taking [xla:1](100) -> md5-e82895d30622d892ecf758d83c95332bxla:1](120): Rate = ~460 img/sec, WallTime = 23 sec

[xla:1](100) Loss=0.00071 Rate=467.26 Time=2019-08-01 21:28:36.382453
[xla:1](120) Loss=0.00081 Rate=454.11 Time=2019-08-01 21:28:59.764112
[xla:2](100) Loss=0.00071 Rate=462.82 Time=2019-08-01 21:28:36.382545
[xla:2](120) Loss=0.00081 Rate=442.44 Time=2019-08-01 21:28:59.764619
[xla:3](100) Loss=0.00071 Rate=432.62 Time=2019-08-01 21:28:36.372789
[xla:3](120) Loss=0.00081 Rate=446.72 Time=2019-08-01 21:28:59.764415
[xla:4](100) Loss=0.00071 Rate=443.22 Time=2019-08-01 21:28:36.372013
[xla:4](120) Loss=0.00081 Rate=444.59 Time=2019-08-01 21:28:59.762870
[xla:5](100) Loss=0.00071 Rate=478.35 Time=2019-08-01 21:28:36.315892
[xla:5](120) Loss=0.00081 Rate=357.39 Time=2019-08-01 21:28:59.764223
[xla:6](100) Loss=0.00071 Rate=466.64 Time=2019-08-01 21:28:36.373583
[xla:6](120) Loss=0.00081 Rate=494.31 Time=2019-08-01 21:28:59.763108
[xla:7](100) Loss=0.00071 Rate=456.01 Time=2019-08-01 21:28:36.321530
[xla:7](120) Loss=0.00081 Rate=426.50 Time=2019-08-01 21:28:59.763020
[xla:8](100) Loss=0.00071 Rate=485.71 Time=2019-08-01 21:28:36.371881
[xla:8](120) Loss=0.00081 Rate=453.02 Time=2019-08-01 21:28:59.763803

Will try profile where the time is being spent.

[jysohn23]

I tried comparing xm.RateTracker()'s measurements against some very raw computation of examples/sec and even for that I get very different results. The diff to print was:

--- a/test/test_train_imagenet.py
+++ b/test/test_train_imagenet.py
@@ -36,6 +36,7 @@ import torch_xla_py.data_parallel as dp
 import torch_xla_py.utils as xu
 import torch_xla_py.xla_model as xm
 import unittest
+import time

 DEFAULT_KWARGS = dict(
     batch_size=128,
@@ -130,8 +131,11 @@ def train_imagenet():
             lr=FLAGS.lr,
             momentum=FLAGS.momentum,
             weight_decay=5e-4))
-    tracker = xm.RateTracker()
+    tracker = xm.RateTracker(smooth_factor=0)
     model.train()
+
+    start = time.time()
+    examples = 0
     for x, (data, target) in loader:
       optimizer.zero_grad()
       output = model(data)
@@ -139,9 +143,13 @@ def train_imagenet():
       loss.backward()
       xm.optimizer_step(optimizer)
       tracker.add(FLAGS.batch_size)
+      examples += FLAGS.batch_size
       if x % FLAGS.log_steps == 0:
-        print('[{}]({}) Loss={:.5f} Rate={:.2f}'.format(device, x, loss.item(),
-                                                        tracker.rate()))
+        print('[{}]({}) Loss={:.5f} Rate={:.2f} (debug)examples/sec={:.2f}'.format(
+            device, x, loss.item(), tracker.rate(),
+            float(examples)/(time.time() - start)))
+        start = time.time()
+        examples = 0

   def test_loop_fn(model, loader, device, context):
     total_samples = 0

Running the above we get:

[xla:8](0) Loss=6.89059 Rate=18.19 (debug)examples/sec=11.80
[xla:1](0) Loss=6.89059 Rate=17.29 (debug)examples/sec=11.42
[xla:3](0) Loss=6.89059 Rate=17.46 (debug)examples/sec=11.49
[xla:4](0) Loss=6.89059 Rate=17.63 (debug)examples/sec=11.47
[xla:2](0) Loss=6.89059 Rate=17.27 (debug)examples/sec=11.29
[xla:6](0) Loss=6.89059 Rate=18.24 (debug)examples/sec=11.59
[xla:5](0) Loss=6.89059 Rate=17.98 (debug)examples/sec=11.51
[xla:7](0) Loss=6.89059 Rate=18.28 (debug)examples/sec=11.60
[xla:4](20) Loss=0.03099 Rate=321.29 (debug)examples/sec=93.01
[xla:7](20) Loss=0.03099 Rate=336.78 (debug)examples/sec=93.33
[xla:5](20) Loss=0.03099 Rate=333.94 (debug)examples/sec=93.22
[xla:2](20) Loss=0.03099 Rate=333.08 (debug)examples/sec=93.15
[xla:1](20) Loss=0.03099 Rate=301.09 (debug)examples/sec=92.68
[xla:8](20) Loss=0.03099 Rate=331.32 (debug)examples/sec=92.68
[xla:6](20) Loss=0.03099 Rate=334.66 (debug)examples/sec=93.09
[xla:3](20) Loss=0.03099 Rate=359.80 (debug)examples/sec=92.59
[xla:6](40) Loss=0.00082 Rate=284.32 (debug)examples/sec=147.57
[xla:4](40) Loss=0.00082 Rate=273.69 (debug)examples/sec=146.23
[xla:3](40) Loss=0.00082 Rate=278.40 (debug)examples/sec=147.02
[xla:2](40) Loss=0.00082 Rate=297.53 (debug)examples/sec=146.69
[xla:5](40) Loss=0.00082 Rate=293.94 (debug)examples/sec=146.69
[xla:7](40) Loss=0.00082 Rate=291.32 (debug)examples/sec=146.65
[xla:1](40) Loss=0.00082 Rate=303.07 (debug)examples/sec=146.74
[xla:8](40) Loss=0.00082 Rate=290.67 (debug)examples/sec=146.72

We get very different examples/sec. Though reading the code actually, does reveal that this is expected. The xm.rate() retrieved is the instantaneous rate from just the previous step. So this hints to some systematic skew of performance such that the batches that are processed before printing the rate are faster whereas the earlier ones are slower.

[jysohn23]

For the value printed at (debug)examples/sec, changing that to be the rate based on only the latest batch of data makes it the exact same as xm.rate().

This explains why the wall time we were seeing for 20 steps doesn't correspond to the xm.rate() based examples/sec; since the xm.rate() uses the smoothing and skews towards the latest values its seen, and the later batches seem to be processed much faster than the previous ones (I believe the current setup in terms of --log_steps and how much prefetching we do is periodic such that we see this consistently).

I'll be trying to check the rate at every step to test this skewed examples/sec behavior.

[jysohn23]

You can clearly see the pattern here. The periodicity seems to correspond to how many number of full batches we decide to prefetch and pre-send to XRT (code).

Per the periodicity of a slow step here's some more data:
device_prefetch_size=4: logs
device_prefetch_size=8: logs

Something is obviously bottlenecked, it doesn't look like its the TransferToServer that is initially slow, but more like it's on the client side that it's bottlenecked every at a period of approximately device_prefetch_size. I'll continue to investigate this bottleneck but I believe there's just not enough overlapping.

[jysohn23]

In my opinion the RateTracker's behavior should be different such that we report the average examples/sec since the last logging event without any smoothing. Smoothing the rate behind the scenes has been very confusing especially in cases when certain steps take much longer. So the rate should be the rate since last report.

Either we should change the behavior of RateTracker.rate() or add another method like RateTracker.rate_since() or similar. I personally think this metric is more useful.

Any thoughts or data points to add? @zcain117 @taylanbil @dlibenzi

[taylanbil]

Instead of smoothing, if we had

num samples processed_since_last_report / num_seconds_since_last_report

that would correspond with the wall time. We can also make use of overall rate, such as:

tracker.begin_tracking() # starts clock
tracker.global_rate() # returns num_samples_processed_since_start / num_seconds_since_start
tracker.rate() # returns num samples processed_since_last_report / num_seconds_since_last_report

[jysohn23]

tracker.begin_tracking() # starts clock

Just a nit, this would just be at __init__ time for xm.RateTracker() as of now.

[taylanbil]

oh sure yeah that's fine. and global_rate exists as well, so I guess what I'm proposing is rate should return the non-smoothed absolute rate since last report, which is exactly what you proposed in the previous msg.

[taylanbil]

Alternatively, if we want to stick w/ smoothing, I'm of the opinion that smoothing every time we report rate instead of every time we update the rate would be a better way. That is, smoothing logic can exist inside .rate(), update would only change counters and thus the reported rate would not be dominated by the last update.

[dlibenzi]

In my opinion the RateTracker's behavior should be different such that we report the average examples/sec since the last logging event without any smoothing. Smoothing the rate behind the scenes has been very confusing especially in cases when certain steps take much longer. So the rate should be the rate since last report.

Either we should change the behavior of RateTracker.rate() or add another method like RateTracker.rate_since() or similar. I personally think this metric is more useful.

Any thoughts or data points to add? @zcain117 @taylanbil @dlibenzi

Without smoothing it will be even worse, as it will jump all over the places. Literally. This is why smoothing was added.
The global_rate() is too smooth, as it won't pick up effectively the current performance.

[jysohn23]

Without smoothing it will be even worse, as it will jump all over the places. Literally. This is why smoothing was added.
The global_rate() is too smooth, as it won't pick up effectively the current performance.

I am confused. Why will it be jumping around all over the place if we average since last logging event (which is what we do with TPUEstimator too) which would be just equal to --log_steps? This accurate representation of their performance is what the user would be interested in, no?

[taylanbil]

@dlibenzi , smoothing is fine, but when we smooth every step and report every 20 steps, what we observe in stdout becomes dominated by the last step, and a bit out of touch with the wall time.

[dlibenzi]

Because then if log_steps=1, like it used to be, there is no smoothing at all.
Smoothing becomes function of log_steps.
Maybe something along these lines (not tested at all, feel free to make a PR):

diff --git a/torch_xla_py/xla_model.py b/torch_xla_py/xla_model.py
index 9b32422..0f46d72 100644
--- a/torch_xla_py/xla_model.py
+++ b/torch_xla_py/xla_model.py
@@ -142,27 +142,30 @@ class RateTracker(object):
     self._start_time = time.time()
     self._partial_time = self._start_time
     self._count = 0
-    self._rate = 0.0
+    self._rate = None

   def update(self, count):
-    now = time.time()
-    delta = now - self._partial_time
-    if delta > 0:
-      rate = (count - self._count) / delta
-      self._rate = (
-          self._rate * self._smooth_factor + rate * (1.0 - self._smooth_factor))
-    self._partial_time = now
+    self._rate = None
     self._count = count
-    return self._rate

   def add(self, count):
-    return self.update(self._count + count)
+    self.update(self._count + count)

   def rate(self):
+    if self._rate is None:
+      now = time.time()
+      delta = now - self._partial_time
+      if delta > 0:
+        rate = (count - self._count) / delta
+        self._rate = (
+            self._rate * self._smooth_factor + rate *
+            (1.0 - self._smooth_factor))
+        self._partial_time = now
     return self._rate

   def global_rate(self):
-    return self._count / (self._partial_time - self._start_time)
+    delta = self._partial_time - self._start_time
+    return self._count / delta if delta > 0 else 0.0


 class TrainStepMetrics(object):

[foobar8675]

@taylanbil is it possible to add how to use xm.RateTracker to the readme or docs ? I spend most my time looking at the DC-GAN example, however, xm.RateTracker is initiated there, but never used. :(

[taylanbil]

have a look at https://www.github.com/pytorch/xla/tree/master/test%2Ftest_train_mp_imagenet.py

[foobar8675]

thank you for responding @taylanbil

based on how rate is called in the imagenet notebook and the source
https://github.com/pytorch/xla/blob/9ff6ac0d0ce77b34f962da790903dbe2c98bdc50/torch_xla/core/xla_model.py#L356

I would guess every time rate is called, it would return the difference in seconds since the last call? in my very simple notebook, it seems to always return 0, and so does the global_rate and I don't really understand why.

https://colab.research.google.com/drive/1yBPfqhglPufj7CyvcuCidIyQCOEaMXNR?usp=sharing

[taylanbil]

you need to tell tracker how many sanples it processed, using something like tracker.add(samplesize). see the example.