tensorflow: WARNING:tensorflow:Method (on_train_batch_end) is slow compared to the batch update (0.112000). Check your callbacks.

This is caused when other operations which runs at the end of each batch consumes longer time than batch themselves. One of the causes might be, we have really smaller batches. So, any operations is slow compared to your original batches.

Increasing batch size actually solved the problem for me.

see @bstriner comment in Link

setting verbose=2 gets rid of the warning

I was having the same warning

Loading model
Epoch 1/3
   2/1688 [..............................] - ETA: 6:36 - loss: 2.2862 - accuracy: 0.1562WARNING:tensorflow:Callbacks method `on_train_batch_end` is slow compared to the batch time (batch time: 0.0027s vs `on_train_batch_end` time: 0.4677s). Check your callbacks.
1688/1688 [==============================] - 5s 3ms/step - loss: 0.4661 - accuracy: 0.8339 - val_loss: 0.3578 - val_accuracy: 0.8735
Epoch 2/3
1688/1688 [==============================] - 4s 2ms/step - loss: 0.3157 - accuracy: 0.8861 - val_loss: 0.2872 - val_accuracy: 0.8923
Epoch 3/3
1688/1688 [==============================] - 4s 2ms/step - loss: 0.2734 - accuracy: 0.8991 - val_loss: 0.2711 - val_accuracy: 0.9012

I could remove the warning by adding profile_batch=0 (to disable profiling) to the Tensorboard callback. Now my call back looks like this,

tbCallBack = TensorBoard(log_dir='logs', update_freq='epoch', write_graph=True, profile_batch=0)

I am using Tensorflow 2.3.0.

Loading model
Epoch 1/3
1688/1688 [==============================] - 4s 2ms/step - loss: 0.4849 - accuracy: 0.8240 - val_loss: 0.3673 - val_accuracy: 0.8658
Epoch 2/3
1688/1688 [==============================] - 4s 2ms/step - loss: 0.3282 - accuracy: 0.8810 - val_loss: 0.3016 - val_accuracy: 0.8902
Epoch 3/3
1688/1688 [==============================] - 4s 2ms/step - loss: 0.2792 - accuracy: 0.8978 - val_loss: 0.2671 - val_accuracy: 0.9022

and below lines removes other warnings.

import os
# To disable all logging output from TensorFlow
os.environ["TF_CPP_MIN_LOG_LEVEL"]="3" 

According to https://www.tensorflow.org/api_docs/python/tf/keras/Model#fit :

verbose: 0, 1, or 2. Verbosity mode. 0 = silent, 1 = progress bar, 2 = one line per epoch. Note that the progress bar is not particularly useful when logged to a file, so verbose=2 is recommended when not running interactively (eg, in a production environment).

So verbose=2 seems to be not that verbose to trigger such a warning: it prints something on epoch end, which is rarer than the batch end. In contrast, they suggest on the internet to change from verbose=1 to verbose=2 in order to avoid such warning, because I guess verbose=1 prints something on every batch.

This may be due to the fact that you’ve given verbose=2 in your fit model. You can try verbose = 1.

@amahendrakar , thanks for your suggestions about suppressing the logs. However, the point missed in this approach is that excessive output from Tensorflow seems to indicate a bug in it. As you can see in the diagram I attached, it looks like a lot of time is spent on a side activity.

Based on this identical discussion in keras-team/keras, this can be solved by setting steps_per_execution=N (where N is a high, positive int) in your model.compile() call. This will cause you to need to specify steps_per_epoch in model.fit(), however.

Hi Everyone,

After using it for a while, I found this is really not a bug. It is just for each training batch, keras is doing some callbacks. The warning shows up because the callback is taking longer than the training itself. It might be that you are doing some expensive ops. Note that other than the callbacks you defined by yourself, keras has some default callbacks, as shown here: https://github.com/tensorflow/tensorflow/blob/582c8d236cb079023657287c318ff26adb239002/tensorflow/python/keras/callbacks.py#L254-L271

I saw exactly the same warning. In my case, it was the problem of the Tensorboard callback. I used batch size of 32 and probably, Tensorboard’s callback took longer for saving and writing log files than an iteration of 32 examples. I had removed Tensorboard from my callbacks’ list and the Warning has been disappeared.

For me the issue also has nothing to do with the callbacks (it persists after removing all callbacks). For me, the warning appears after I either increase my batch size from 32 to 64 or increase my image width from 32 to 64 pixels.

Hi. This problem occurred when I used custom callbacks that took a long time in <= 2.2. I solved this problem by hacking a small part of CallbackList. The warning message is due to this.

class CallbackList(object):
..
..
    def _call_batch_hook(self, mode, hook, batch, logs=None):
        """Helper function for all batch_{begin | end} methods."""
        if not self.callbacks:
            return
        hook_name = 'on_{mode}_batch_{hook}'.format(mode=mode, hook=hook)
        if hook == 'begin':
            self._t_enter_batch = time.time()
        if hook == 'end':
            # Batch is ending, calculate batch time.
            self._delta_t_batch = time.time() - self._t_enter_batch

        logs = logs or {}
        t_before_callbacks = time.time()
        for callback in self.callbacks:
            batch_hook = getattr(callback, hook_name)
            batch_hook(batch, logs)
        self._delta_ts[hook_name].append(time.time() - t_before_callbacks)

        delta_t_median = np.median(self._delta_ts[hook_name])
        if (self._delta_t_batch > 0. and
              delta_t_median > 0.95 * self._delta_t_batch and delta_t_median > 0.1):
            # here is the warning message!
            logging.warning(
                'Method (%s) is slow compared '
                'to the batch update (%f). Check your callbacks.', hook_name, 
                delta_t_median)
..
..

If you don’t need to check the time of your callbacks, you can delete the message and assign a new CallbackList to the original CallbackList as below.

from tensorflow.python.keras.callbacks import CallbackList
class CustomCallbackList(CallbackList):
    def _call_batch_hook(self, mode, hook, batch, logs=None):
        """Helper function for all batch_{begin | end} methods."""
        if not self.callbacks:
            return
        hook_name = 'on_{mode}_batch_{hook}'.format(mode=mode, hook=hook)

        logs = logs or {}
        for callback in self.callbacks:
            batch_hook = getattr(callback, hook_name)
            batch_hook(batch, logs)

tf.python.keras.callbacks.CallbackList = CustomCallbackList

Did this work for you? It’s giving me an error. AttributeError: module 'tensorflow' has no attribute 'python' Besides, I think this isn’t really solving the problem. It may eliminate the error message but the on_train_batch_end will be still taking longer than the learning itself. I have no callbacks and I want to fix this. Nice idea looking at the source code anyway.

If tensorflow is in the environment used, the error you mentioned does not appear. You can check it in my example. Of course, it just removes the message as you said. If you already know that on_train_batch_end has heavy operations, it is very utilizable. Otherwise, check your train_step loop whether any problem exists.

Pardon, but what do you mean by ‘If tensorflow is in the environment used’?

About the original problem of this thread… I’m getting the error even without any heavy operations in the callbacks. Can a problem inside a train_step loop cause this problem? I looked at the source code and I believe the order of the issue is like below. However, the code seems it’s just because of the callbacks’ on_train_batch_end.

https://github.com/keras-team/keras/blob/master/keras/engine/training.py#L1118 https://github.com/tensorflow/tensorflow/blob/r2.2/tensorflow/python/keras/callbacks.py#L381 https://github.com/tensorflow/tensorflow/blob/r2.2/tensorflow/python/keras/callbacks.py#L304

To be more specific with my issue, I don’t get the error if I don’t use any callbacks, but the total elapsed time in one epoch is the same. Also, the error appears only at first and doesn’t appear anymore afterward. Thank you.

The reason I mentioned train_step loop is that operations in train_step may not work properly. As you said, this message due to delta_t_median > 0.95 * self._delta_t_batch and delta_t_median > 0.1 is only printed when you have callbacks. If this message came out only once, it was just a message under that condition. I think the warning was issued because it took some time to initialize, such as on_epoch_begin or on_train_batch_begin. There are no other problems.

Hi. This problem occurred when I used custom callbacks that took a long time in <= 2.2. I solved this problem by hacking a small part of CallbackList.

The warning message is due to this.

class CallbackList(object):
..
..
    def _call_batch_hook(self, mode, hook, batch, logs=None):
        """Helper function for all batch_{begin | end} methods."""
        if not self.callbacks:
            return
        hook_name = 'on_{mode}_batch_{hook}'.format(mode=mode, hook=hook)
        if hook == 'begin':
            self._t_enter_batch = time.time()
        if hook == 'end':
            # Batch is ending, calculate batch time.
            self._delta_t_batch = time.time() - self._t_enter_batch

        logs = logs or {}
        t_before_callbacks = time.time()
        for callback in self.callbacks:
            batch_hook = getattr(callback, hook_name)
            batch_hook(batch, logs)
        self._delta_ts[hook_name].append(time.time() - t_before_callbacks)

        delta_t_median = np.median(self._delta_ts[hook_name])
        if (self._delta_t_batch > 0. and
              delta_t_median > 0.95 * self._delta_t_batch and delta_t_median > 0.1):
            # here is the warning message!
            logging.warning(
                'Method (%s) is slow compared '
                'to the batch update (%f). Check your callbacks.', hook_name, 
                delta_t_median)
..
..

If you don’t need to check the time of your callbacks, you can delete the message and assign a new CallbackList to the original CallbackList as below.

from tensorflow.python.keras.callbacks import CallbackList
class CustomCallbackList(CallbackList):
    def _call_batch_hook(self, mode, hook, batch, logs=None):
        """Helper function for all batch_{begin | end} methods."""
        if not self.callbacks:
            return
        hook_name = 'on_{mode}_batch_{hook}'.format(mode=mode, hook=hook)

        logs = logs or {}
        for callback in self.callbacks:
            batch_hook = getattr(callback, hook_name)
            batch_hook(batch, logs)

tf.python.keras.callbacks.CallbackList = CustomCallbackList

Running tf2.3rc2 on TPU and I am facing the same issue as well.

@srogatch, The verbose argument lets you control what output you see on each epoch. For more information please check this StackOverflow comment.

Regarding the warning logs, could you please try changing the logging level and check if it works?

import os
os.environ["TF_CPP_MIN_LOG_LEVEL"] = "2"
import tensorflow as tf

Thanks!