Slow eval time (+2s per iter)

[ExtReMLapin]

Hello, any idea why my eval time is so slow ?

[02/20 14:03:39 d2.data.dataset_mapper]: [DatasetMapper] Augmentations used in inference: [ResizeShortestEdge(short_edge_length=(800, 800), max_size=1333, sample_style='choice')]
[02/20 14:03:39 d2.data.common]: Serializing the dataset using: <class 'detectron2.data.common._TorchSerializedList'>
[02/20 14:03:39 d2.data.common]: Serializing 702 elements to byte tensors and concatenating them all ...
[02/20 14:03:39 d2.data.common]: Serialized dataset takes 1.16 MiB
[02/20 14:03:39 d2.evaluation.evaluator]: Start inference on 702 batches
[02/20 14:04:05 d2.evaluation.evaluator]: Inference done 11/702. Dataloading: 0.0012 s/iter. Inference: 0.1243 s/iter. Eval: 1.8036 s/iter. Total: 1.9292 s/iter. ETA=0:22:13
[02/20 14:04:12 d2.evaluation.evaluator]: Inference done 14/702. Dataloading: 0.0011 s/iter. Inference: 0.1263 s/iter. Eval: 1.9267 s/iter. Total: 2.0544 s/iter. ETA=0:23:33
[02/20 14:04:18 d2.evaluation.evaluator]: Inference done 17/702. Dataloading: 0.0011 s/iter. Inference: 0.1230 s/iter. Eval: 1.8892 s/iter. Total: 2.0135 s/iter. ETA=0:22:59
[02/20 14:04:25 d2.evaluation.evaluator]: Inference done 20/702. Dataloading: 0.0011 s/iter. Inference: 0.1243 s/iter. Eval: 1.9435 s/iter. Total: 2.0692 s/iter. ETA=0:23:31
[02/20 14:04:32 d2.evaluation.evaluator]: Inference done 23/702. Dataloading: 0.0011 s/iter. Inference: 0.1253 s/iter. Eval: 1.9814 s/iter. Total: 2.1080 s/iter. ETA=0:23:51
[02/20 14:04:39 d2.evaluation.evaluator]: Inference done 26/702. Dataloading: 0.0011 s/iter. Inference: 0.1262 s/iter. Eval: 2.0122 s/iter. Total: 2.1398 s/iter. ETA=0:24:06
[02/20 14:04:44 d2.evaluation.evaluator]: Inference done 27/702. Dataloading: 0.0011 s/iter. Inference: 0.1299 s/iter. Eval: 2.1416 s/iter. Total: 2.2729 s/iter. ETA=0:25:34
[02/20 14:04:49 d2.evaluation.evaluator]: Inference done 30/702. Dataloading: 0.0011 s/iter. Inference: 0.1275 s/iter. Eval: 2.0896 s/iter. Total: 2.2186 s/iter. ETA=0:24:50
[02/20 14:04:58 d2.evaluation.evaluator]: Inference done 34/702. Dataloading: 0.0012 s/iter. Inference: 0.1264 s/iter. Eval: 2.0964 s/iter. Total: 2.2243 s/iter. ETA=0:24:45
[02/20 14:05:04 d2.evaluation.evaluator]: Inference done 38/702. Dataloading: 0.0015 s/iter. Inference: 0.1232 s/iter. Eval: 1.9924 s/iter. Total: 2.1174 s/iter. ETA=0:23:25
[02/20 14:05:13 d2.evaluation.evaluator]: Inference done 41/702. Dataloading: 0.0015 s/iter. Inference: 0.1263 s/iter. Eval: 2.0831 s/iter. Total: 2.2111 s/iter. ETA=0:24:21
[02/20 14:05:20 d2.evaluation.evaluator]: Inference done 44/702. Dataloading: 0.0014 s/iter. Inference: 0.1266 s/iter. Eval: 2.0937 s/iter. Total: 2.2221 s/iter. ETA=0:24:22
[02/20 14:05:26 d2.evaluation.evaluator]: Inference done 48/702. Dataloading: 0.0014 s/iter. Inference: 0.1236 s/iter. Eval: 2.0217 s/iter. Total: 2.1470 s/iter. ETA=0:23:24
[02/20 14:05:31 d2.evaluation.evaluator]: Inference done 51/702. Dataloading: 0.0014 s/iter. Inference: 0.1226 s/iter. Eval: 1.9981 s/iter. Total: 2.1224 s/iter. ETA=0:23:01
[02/20 14:05:36 d2.evaluation.evaluator]: Inference done 52/702. Dataloading: 0.0013 s/iter. Inference: 0.1243 s/iter. Eval: 2.0577 s/iter. Total: 2.1836 s/iter. ETA=0:23:39
[02/20 14:05:42 d2.evaluation.evaluator]: Inference done 54/702. Dataloading: 0.0013 s/iter. Inference: 0.1251 s/iter. Eval: 2.0852 s/iter. Total: 2.2119 s/iter. ETA=0:23:53
[02/20 14:05:50 d2.evaluation.evaluator]: Inference done 57/702. Dataloading: 0.0013 s/iter. Inference: 0.1255 s/iter. Eval: 2.1040 s/iter. Total: 2.2311 s/iter. ETA=0:23:59
[02/20 14:05:57 d2.evaluation.evaluator]: Inference done 59/702. Dataloading: 0.0013 s/iter. Inference: 0.1271 s/iter. Eval: 2.1555 s/iter. Total: 2.2842 s/iter. ETA=0:24:28
[02/20 14:06:05 d2.evaluation.evaluator]: Inference done 61/702. Dataloading: 0.0013 s/iter. Inference: 0.1286 s/iter. Eval: 2.2073 s/iter. Total: 2.3376 s/iter. ETA=0:24:58
[02/20 14:06:10 d2.evaluation.evaluator]: Inference done 63/702. Dataloading: 0.0013 s/iter. Inference: 0.1291 s/iter. Eval: 2.2176 s/iter. Total: 2.3484 s/iter. ETA=0:25:00
[02/20 14:06:17 d2.evaluation.evaluator]: Inference done 66/702. Dataloading: 0.0014 s/iter. Inference: 0.1298 s/iter. Eval: 2.2126 s/iter. Total: 2.3440 s/iter. ETA=0:24:50
[02/20 14:06:24 d2.evaluation.evaluator]: Inference done 69/702. Dataloading: 0.0015 s/iter. Inference: 0.1300 s/iter. Eval: 2.2116 s/iter. Total: 2.3435 s/iter. ETA=0:24:43
[02/20 14:06:29 d2.evaluation.evaluator]: Inference done 72/702. Dataloading: 0.0017 s/iter. Inference: 0.1293 s/iter. Eval: 2.1919 s/iter. Total: 2.3232 s/iter. ETA=0:24:23
[02/20 14:06:37 d2.evaluation.evaluator]: Inference done 74/702. Dataloading: 0.0017 s/iter. Inference: 0.1304 s/iter. Eval: 2.2360 s/iter. Total: 2.3684 s/iter. ETA=0:24:47
[02/20 14:06:46 d2.evaluation.evaluator]: Inference done 77/702. Dataloading: 0.0018 s/iter. Inference: 0.1308 s/iter. Eval: 2.2638 s/iter. Total: 2.3967 s/iter. ETA=0:24:57
[02/20 14:06:54 d2.evaluation.evaluator]: Inference done 80/702. Dataloading: 0.0018 s/iter. Inference: 0.1286 s/iter. Eval: 2.2781 s/iter. Total: 2.4089 s/iter. ETA=0:24:58
[02/20 14:07:02 d2.evaluation.evaluator]: Inference done 81/702. Dataloading: 0.0019 s/iter. Inference: 0.1287 s/iter. Eval: 2.3455 s/iter. Total: 2.4763 s/iter. ETA=0:25:37
[02/20 14:07:10 d2.evaluation.evaluator]: Inference done 82/702. Dataloading: 0.0020 s/iter. Inference: 0.1288 s/iter. Eval: 2.4124 s/iter. Total: 2.5435 s/iter. ETA=0:26:16
[02/20 14:07:19 d2.evaluation.evaluator]: Inference done 84/702. Dataloading: 0.0021 s/iter. Inference: 0.1288 s/iter. Eval: 2.4723 s/iter. Total: 2.6035 s/iter. ETA=0:26:48
[02/20 14:07:25 d2.evaluation.evaluator]: Inference done 88/702. Dataloading: 0.0023 s/iter. Inference: 0.1300 s/iter. Eval: 2.4078 s/iter. Total: 2.5405 s/iter. ETA=0:25:59
[02/20 14:07:30 d2.evaluation.evaluator]: Inference done 90/702. Dataloading: 0.0023 s/iter. Inference: 0.1302 s/iter. Eval: 2.4135 s/iter. Total: 2.5464 s/iter. ETA=0:25:58
[02/20 14:07:36 d2.evaluation.evaluator]: Inference done 91/702. Dataloading: 0.0024 s/iter. Inference: 0.1313 s/iter. Eval: 2.4467 s/iter. Total: 2.5808 s/iter. ETA=0:26:16
[02/20 14:07:42 d2.evaluation.evaluator]: Inference done 94/702. Dataloading: 0.0025 s/iter. Inference: 0.1319 s/iter. Eval: 2.4253 s/iter. Total: 2.5601 s/iter. ETA=0:25:56
[02/20 14:07:49 d2.evaluation.evaluator]: Inference done 97/702. Dataloading: 0.0026 s/iter. Inference: 0.1325 s/iter. Eval: 2.4185 s/iter. Total: 2.5540 s/iter. ETA=0:25:45
[02/20 14:07:55 d2.evaluation.evaluator]: Inference done 99/702. Dataloading: 0.0027 s/iter. Inference: 0.1327 s/iter. Eval: 2.4265 s/iter. Total: 2.5622 s/iter. ETA=0:25:45

this is my eval/train code

class CocoTrainer(DefaultTrainer):

  @classmethod
  def build_evaluator(cls, cfg, dataset_name, output_folder=None):

    if output_folder is None:
        os.makedirs("coco_eval", exist_ok=True)
        output_folder = "coco_eval"

    return COCOEvaluator(dataset_name, "segm", True, output_folder, use_fast_impl =True, allow_cached_coco =True)
  
os.makedirs(cfg.OUTPUT_DIR, exist_ok=True)
trainer = CocoTrainer(cfg)
trainer.resume_or_load(resume=False)
trainer.train()

[ExtReMLapin]

from memory I also had this issue on our windows machine, I feel like it could be related to the fact we're not using the prebuilt version

[d12]

I'm seeing the same, did you ever sort this out @ExtReMLapin ? I'm trying to run validation regularly during training but the slow eval time is really blowing up the amount of time training takes.

[ExtReMLapin]

Nope, i gave up and stop using detectron

[ExtReMLapin]

Did you find anything @d12 ?

[d12]

I found it's especially slow for images with large numbers of annotations. I did some training where I tiled my dataset and that helped a lot. But I mainly just ran evaluation less frequently.

I remember some way to use a "fast evaluator" with Detectron2 but I couldn't fully make it work. I don't have the source or references handy right now, it was in the detectron2 source though.

[ExtReMLapin]

I found what was causing it :

COCOEvaluator.process is slow because of two calls :

                instances = output["instances"].to(self._cpu_device)
                prediction["instances"] = instances_to_coco_json(instances, input["image_id"])

    Time to move to CPU:  0.4057140350341797

    Time to process instance:  0.6593849658966064