class CustomPythonFormatter(PythonFormatter):
"""Logging Formatter to add colors and custom format string
adapted from https://stackoverflow.com/q/64263526 (author: MaKaNu)
"""
blue = "\x1b[34;21m"
green = "\x1b[32;21m"
yellow = "\x1b[33;21m"
red = "\x1b[31;21m"
bold_red = "\x1b[31;1m"
grey = "\x1b[38;5;246m"
reset_color = "\x1b[0m"
format_str = "%(levelname)s" + reset_color + " - %(funcName)s()\n »»» " + grey + \
" %(message)s \n" + reset_color
date_format = "%Y-%m-%d %H:%M:%S"
FORMATS = {
"DEBUG":
logging.PythonFormatter(fmt=blue + format_str, datefmt=date_format),
"INFO":
logging.PythonFormatter(fmt=green + format_str, datefmt=date_format),
"WARNING":
logging.PythonFormatter(fmt=yellow + format_str, datefmt=date_format),
"ERROR":
logging.PythonFormatter(fmt=red + format_str, datefmt=date_format),
"FATAL":
logging.PythonFormatter(fmt=bold_red + format_str, datefmt=date_format)
}
def format(self, record: LogRecord):
formatter = self.FORMATS.get(record.levelname, self.FORMATS["INFO"])
return formatter.format(record)
def setUp(self):
self.now_tuple = time.localtime(time.mktime(
(1979, 10, 21, 18, 17, 16, 3, 15, 1)))
self.new_prefix = lambda level: '(blah_prefix)'
mock.patch.object(time, 'time').start()
mock.patch.object(time, 'localtime').start()
self.record = std_logging.LogRecord(
'name', std_logging.INFO, 'path', 12, 'A Message', [], False)
self.formatter = logging.PythonFormatter()
def add_log_file(logfile):
"""Replicate logs to an additional logfile.
The caller is responsible for closing the logfile.
Args:
logfile: Open file to write log to
"""
handler = logging.StreamHandler(logfile)
handler.setFormatter(absl_logging.PythonFormatter())
absl_logger = logging.getLogger('absl')
absl_logger.addHandler(handler)
def main(argv):
fmt = '[%(filename)s:%(lineno)s] %(message)s'
formatter = logging.PythonFormatter(fmt)
logging.get_absl_handler().setFormatter(formatter)
del argv # unused arg
tf.io.gfile.makedirs(FLAGS.output_dir)
logging.info('Saving checkpoints at %s', FLAGS.output_dir)
tf.random.set_seed(FLAGS.seed)
data_dir = None
if FLAGS.use_gpu:
logging.info('Use GPU')
strategy = tf.distribute.MirroredStrategy()
else:
logging.info('Use TPU at %s',
FLAGS.tpu if FLAGS.tpu is not None else 'local')
data_dir = FLAGS.data_dir
resolver = tf.distribute.cluster_resolver.TPUClusterResolver(
tpu=FLAGS.tpu)
tf.config.experimental_connect_to_cluster(resolver)
tf.tpu.experimental.initialize_tpu_system(resolver)
strategy = tf.distribute.TPUStrategy(resolver)
ds_info = tfds.builder(FLAGS.dataset).info
batch_size = FLAGS.per_core_batch_size * FLAGS.num_cores
train_dataset_size = (ds_info.splits['train'].num_examples *
FLAGS.train_proportion)
steps_per_epoch = int(train_dataset_size / batch_size)
logging.info('Steps per epoch %s', steps_per_epoch)
logging.info('Size of the dataset %s',
ds_info.splits['train'].num_examples)
logging.info('Train proportion %s', FLAGS.train_proportion)
steps_per_eval = ds_info.splits['test'].num_examples // batch_size
num_classes = ds_info.features['label'].num_classes
aug_params = {
'augmix': FLAGS.augmix,
'aug_count': FLAGS.aug_count,
'augmix_depth': FLAGS.augmix_depth,
'augmix_prob_coeff': FLAGS.augmix_prob_coeff,
'augmix_width': FLAGS.augmix_width,
}
# Note that stateless_{fold_in,split} may incur a performance cost, but a
# quick side-by-side test seemed to imply this was minimal.
seeds = tf.random.experimental.stateless_split(
[FLAGS.seed, FLAGS.seed + 1], 2)[:, 0]
train_builder = ub.datasets.get(FLAGS.dataset,
download_data=FLAGS.download_data,
split=tfds.Split.TRAIN,
seed=seeds[0],
aug_params=aug_params,
validation_percent=1. -
FLAGS.train_proportion,
data_dir=data_dir)
train_dataset = train_builder.load(batch_size=batch_size)
validation_dataset = None
steps_per_validation = 0
if FLAGS.train_proportion < 1.0:
validation_builder = ub.datasets.get(FLAGS.dataset,
split=tfds.Split.VALIDATION,
validation_percent=1. -
FLAGS.train_proportion,
data_dir=data_dir)
validation_dataset = validation_builder.load(batch_size=batch_size)
validation_dataset = strategy.experimental_distribute_dataset(
validation_dataset)
steps_per_validation = validation_builder.num_examples // batch_size
clean_test_builder = ub.datasets.get(FLAGS.dataset,
split=tfds.Split.TEST,
data_dir=data_dir)
clean_test_dataset = clean_test_builder.load(batch_size=batch_size)
train_dataset = strategy.experimental_distribute_dataset(train_dataset)
test_datasets = {
'clean': strategy.experimental_distribute_dataset(clean_test_dataset),
}
steps_per_epoch = train_builder.num_examples // batch_size
steps_per_eval = clean_test_builder.num_examples // batch_size
num_classes = 100 if FLAGS.dataset == 'cifar100' else 10
if FLAGS.corruptions_interval > 0:
if FLAGS.dataset == 'cifar100':
data_dir = FLAGS.cifar100_c_path
corruption_types, _ = utils.load_corrupted_test_info(FLAGS.dataset)
for corruption_type in corruption_types:
for severity in range(1, 6):
dataset = ub.datasets.get(
f'{FLAGS.dataset}_corrupted',
corruption_type=corruption_type,
severity=severity,
split=tfds.Split.TEST,
data_dir=data_dir).load(batch_size=batch_size)
test_datasets[f'{corruption_type}_{severity}'] = (
strategy.experimental_distribute_dataset(dataset))
summary_writer = tf.summary.create_file_writer(
os.path.join(FLAGS.output_dir, 'summaries'))
with strategy.scope():
logging.info('Building ResNet model')
model = ub.models.wide_resnet(input_shape=(32, 32, 3),
depth=28,
width_multiplier=10,
num_classes=num_classes,
l2=FLAGS.l2,
hps=_extract_hyperparameter_dictionary(),
seed=seeds[1],
version=2)
logging.info('Model input shape: %s', model.input_shape)
logging.info('Model output shape: %s', model.output_shape)
logging.info('Model number of weights: %s', model.count_params())
# Linearly scale learning rate and the decay epochs by vanilla settings.
base_lr = FLAGS.base_learning_rate * batch_size / 128
lr_decay_epochs = [(int(start_epoch_str) * FLAGS.train_epochs) // 200
for start_epoch_str in FLAGS.lr_decay_epochs]
lr_schedule = ub.schedules.WarmUpPiecewiseConstantSchedule(
steps_per_epoch,
base_lr,
decay_ratio=FLAGS.lr_decay_ratio,
decay_epochs=lr_decay_epochs,
warmup_epochs=FLAGS.lr_warmup_epochs)
optimizer = tf.keras.optimizers.SGD(lr_schedule,
momentum=1.0 -
FLAGS.one_minus_momentum,
nesterov=True)
metrics = {
'train/negative_log_likelihood':
tf.keras.metrics.Mean(),
'train/accuracy':
tf.keras.metrics.SparseCategoricalAccuracy(),
'train/loss':
tf.keras.metrics.Mean(),
'train/ece':
rm.metrics.ExpectedCalibrationError(num_bins=FLAGS.num_bins),
'test/negative_log_likelihood':
tf.keras.metrics.Mean(),
'test/accuracy':
tf.keras.metrics.SparseCategoricalAccuracy(),
'test/ece':
rm.metrics.ExpectedCalibrationError(num_bins=FLAGS.num_bins),
}
if validation_dataset:
metrics.update({
'validation/negative_log_likelihood':
tf.keras.metrics.Mean(),
'validation/accuracy':
tf.keras.metrics.SparseCategoricalAccuracy(),
'validation/ece':
rm.metrics.ExpectedCalibrationError(num_bins=FLAGS.num_bins),
})
if FLAGS.corruptions_interval > 0:
corrupt_metrics = {}
for intensity in range(1, 6):
for corruption in corruption_types:
dataset_name = '{0}_{1}'.format(corruption, intensity)
corrupt_metrics['test/nll_{}'.format(dataset_name)] = (
tf.keras.metrics.Mean())
corrupt_metrics['test/accuracy_{}'.format(
dataset_name)] = (
tf.keras.metrics.SparseCategoricalAccuracy())
corrupt_metrics['test/ece_{}'.format(dataset_name)] = (
rm.metrics.ExpectedCalibrationError(
num_bins=FLAGS.num_bins))
checkpoint = tf.train.Checkpoint(model=model, optimizer=optimizer)
latest_checkpoint = tf.train.latest_checkpoint(FLAGS.output_dir)
initial_epoch = 0
if latest_checkpoint:
# checkpoint.restore must be within a strategy.scope() so that optimizer
# slot variables are mirrored.
checkpoint.restore(latest_checkpoint)
logging.info('Loaded checkpoint %s', latest_checkpoint)
initial_epoch = optimizer.iterations.numpy() // steps_per_epoch
@tf.function
def train_step(iterator):
"""Training StepFn."""
def step_fn(inputs):
"""Per-Replica StepFn."""
images = inputs['features']
labels = inputs['labels']
if FLAGS.augmix and FLAGS.aug_count >= 1:
# Index 0 at augmix processing is the unperturbed image.
# We take just 1 augmented image from the returned augmented images.
images = images[:, 1, ...]
with tf.GradientTape() as tape:
logits = model(images, training=True)
if FLAGS.label_smoothing == 0.:
negative_log_likelihood = tf.reduce_mean(
tf.keras.losses.sparse_categorical_crossentropy(
labels, logits, from_logits=True))
else:
one_hot_labels = tf.one_hot(tf.cast(labels, tf.int32),
num_classes)
negative_log_likelihood = tf.reduce_mean(
tf.keras.losses.categorical_crossentropy(
one_hot_labels,
logits,
from_logits=True,
label_smoothing=FLAGS.label_smoothing))
l2_loss = sum(model.losses)
loss = negative_log_likelihood + l2_loss
# Scale the loss given the TPUStrategy will reduce sum all gradients.
scaled_loss = loss / strategy.num_replicas_in_sync
grads = tape.gradient(scaled_loss, model.trainable_variables)
optimizer.apply_gradients(zip(grads, model.trainable_variables))
probs = tf.nn.softmax(logits)
metrics['train/ece'].add_batch(probs, label=labels)
metrics['train/loss'].update_state(loss)
metrics['train/negative_log_likelihood'].update_state(
negative_log_likelihood)
metrics['train/accuracy'].update_state(labels, logits)
for _ in tf.range(tf.cast(steps_per_epoch, tf.int32)):
strategy.run(step_fn, args=(next(iterator), ))
@tf.function
def test_step(iterator, dataset_split, dataset_name, num_steps):
"""Evaluation StepFn."""
def step_fn(inputs):
"""Per-Replica StepFn."""
images = inputs['features']
labels = inputs['labels']
logits = model(images, training=False)
probs = tf.nn.softmax(logits)
negative_log_likelihood = tf.reduce_mean(
tf.keras.losses.sparse_categorical_crossentropy(labels, probs))
if dataset_name == 'clean':
metrics[
f'{dataset_split}/negative_log_likelihood'].update_state(
negative_log_likelihood)
metrics[f'{dataset_split}/accuracy'].update_state(
labels, probs)
metrics[f'{dataset_split}/ece'].add_batch(probs, label=labels)
else:
corrupt_metrics['test/nll_{}'.format(
dataset_name)].update_state(negative_log_likelihood)
corrupt_metrics['test/accuracy_{}'.format(
dataset_name)].update_state(labels, probs)
corrupt_metrics['test/ece_{}'.format(dataset_name)].add_batch(
probs, label=labels)
for _ in tf.range(tf.cast(num_steps, tf.int32)):
strategy.run(step_fn, args=(next(iterator), ))
metrics.update({'test/ms_per_example': tf.keras.metrics.Mean()})
metrics.update({'train/ms_per_example': tf.keras.metrics.Mean()})
train_iterator = iter(train_dataset)
start_time = time.time()
tb_callback = None
if FLAGS.collect_profile:
tb_callback = tf.keras.callbacks.TensorBoard(profile_batch=(100, 102),
log_dir=os.path.join(
FLAGS.output_dir,
'logs'))
tb_callback.set_model(model)
for epoch in range(initial_epoch, FLAGS.train_epochs):
logging.info('Starting to run epoch: %s', epoch)
if tb_callback:
tb_callback.on_epoch_begin(epoch)
train_start_time = time.time()
train_step(train_iterator)
ms_per_example = (time.time() - train_start_time) * 1e6 / batch_size
metrics['train/ms_per_example'].update_state(ms_per_example)
current_step = (epoch + 1) * steps_per_epoch
max_steps = steps_per_epoch * FLAGS.train_epochs
time_elapsed = time.time() - start_time
steps_per_sec = float(current_step) / time_elapsed
eta_seconds = (max_steps - current_step) / steps_per_sec
message = ('{:.1%} completion: epoch {:d}/{:d}. {:.1f} steps/s. '
'ETA: {:.0f} min. Time elapsed: {:.0f} min'.format(
current_step / max_steps, epoch + 1, FLAGS.train_epochs,
steps_per_sec, eta_seconds / 60, time_elapsed / 60))
logging.info(message)
if tb_callback:
tb_callback.on_epoch_end(epoch)
if validation_dataset:
validation_iterator = iter(validation_dataset)
test_step(validation_iterator, 'validation', 'clean',
steps_per_validation)
datasets_to_evaluate = {'clean': test_datasets['clean']}
if (FLAGS.corruptions_interval > 0
and (epoch + 1) % FLAGS.corruptions_interval == 0):
datasets_to_evaluate = test_datasets
for dataset_name, test_dataset in datasets_to_evaluate.items():
test_iterator = iter(test_dataset)
logging.info('Testing on dataset %s', dataset_name)
logging.info('Starting to run eval at epoch: %s', epoch)
test_start_time = time.time()
test_step(test_iterator, 'test', dataset_name, steps_per_eval)
ms_per_example = (time.time() - test_start_time) * 1e6 / batch_size
metrics['test/ms_per_example'].update_state(ms_per_example)
logging.info('Done with testing on %s', dataset_name)
corrupt_results = {}
if (FLAGS.corruptions_interval > 0
and (epoch + 1) % FLAGS.corruptions_interval == 0):
corrupt_results = utils.aggregate_corrupt_metrics(
corrupt_metrics, corruption_types)
logging.info('Train Loss: %.4f, Accuracy: %.2f%%',
metrics['train/loss'].result(),
metrics['train/accuracy'].result() * 100)
logging.info('Test NLL: %.4f, Accuracy: %.2f%%',
metrics['test/negative_log_likelihood'].result(),
metrics['test/accuracy'].result() * 100)
total_results = {
name: metric.result()
for name, metric in metrics.items()
}
total_results.update(corrupt_results)
# Metrics from Robustness Metrics (like ECE) will return a dict with a
# single key/value, instead of a scalar.
total_results = {
k: (list(v.values())[0] if isinstance(v, dict) else v)
for k, v in total_results.items()
}
with summary_writer.as_default():
for name, result in total_results.items():
tf.summary.scalar(name, result, step=epoch + 1)
for metric in metrics.values():
metric.reset_states()
if (FLAGS.checkpoint_interval > 0
and (epoch + 1) % FLAGS.checkpoint_interval == 0):
checkpoint_name = checkpoint.save(
os.path.join(FLAGS.output_dir, 'checkpoint'))
logging.info('Saved checkpoint to %s', checkpoint_name)
final_checkpoint_name = checkpoint.save(
os.path.join(FLAGS.output_dir, 'checkpoint'))
logging.info('Saved last checkpoint to %s', final_checkpoint_name)
with summary_writer.as_default():
hp.hparams({
'base_learning_rate': FLAGS.base_learning_rate,
'one_minus_momentum': FLAGS.one_minus_momentum,
'l2': FLAGS.l2,
})
def setUp(self): formatter = logging.PythonFormatter() self.absl_handler = logging.ABSLHandler(formatter)
def add_gfile_logger(workdir, *, basename='train', level=python_logging.INFO):
"""Adds GFile file logger to Python logging handlers."""
fh = GFileHandler(f'{workdir}/{basename}.log', 'a')
fh.setLevel(level)
fh.setFormatter(logging.PythonFormatter())
python_logging.getLogger('').addHandler(fh)
