Some logging thoughts

[johnbrownlow]

I use the log a lot to check performance... I have a couple of thoughts.

1. Could we have an iteration/sec datum for each generation? It currently only logs the time but it/sec is more useful if you're varying the number of steps (since you can't tell this from the log)

2. The 'Prep time' figure seems a bit odd... maybe reports the time from the moment the generation is queued? But when you generate multiple images it's not very helpful (see below). It seems like it would be more useful if it reported the time between the last gen. finishing and the next one beginning, to take account of loading new models or whatever? Currently it mostly just adds up the time the image sat there waiting for other images to finish. But maybe this is helpful for other people?

08:28:14.878 [Info] User local requested 100 images with model 'v1-5-pruned-emaonly.safetensors'...
08:28:31.784 [Info] Generated an image in 9.30 (prep) and 7.58 (gen) seconds
08:28:37.144 [Info] Generated an image in 16.80 (prep) and 5.36 (gen) seconds
08:28:42.153 [Info] Generated an image in 22.13 (prep) and 5.02 (gen) seconds
08:28:47.414 [Info] Generated an image in 27.11 (prep) and 5.25 (gen) seconds
08:28:52.442 [Info] Generated an image in 32.33 (prep) and 5.03 (gen) seconds
08:28:57.801 [Info] Generated an image in 20.64 (prep) and 5.34 (gen) seconds
08:29:02.924 [Info] Generated an image in 20.63 (prep) and 5.14 (gen) seconds
08:29:08.222 [Info] Generated an image in 20.75 (prep) and 5.30 (gen) seconds
08:29:13.261 [Info] Generated an image in 20.78 (prep) and 5.03 (gen) seconds
08:29:18.633 [Info] Generated an image in 10.31 (prep) and 5.38 (gen) seconds
08:29:23.714 [Info] Generated an image in 10.39 (prep) and 5.08 (gen) seconds
08:29:29.036 [Info] Generated an image in 10.42 (prep) and 5.33 (gen) seconds
08:29:34.115 [Info] Generated an image in 10.39 (prep) and 5.06 (gen) seconds
08:29:39.403 [Info] Generated an image in 10.38 (prep) and 5.30 (gen) seconds
08:29:44.474 [Info] Generated an image in 10.34 (prep) and 5.06 (gen) seconds
08:29:49.780 [Info] Generated an image in 10.33 (prep) and 5.31 (gen) seconds
08:29:54.840 [Info] Generated an image in 10.36 (prep) and 5.06 (gen) seconds
08:30:00.219 [Info] Generated an image in 10.34 (prep) and 5.38 (gen) seconds
08:30:05.284 [Info] Generated an image in 10.42 (prep) and 5.06 (gen) seconds
08:30:10.581 [Info] Generated an image in 10.42 (prep) and 5.30 (gen) seconds
08:30:15.680 [Info] Generated an image in 10.34 (prep) and 5.09 (gen) seconds
08:30:20.982 [Info] Generated an image in 10.36 (prep) and 5.31 (gen) seconds
08:30:25.997 [Info] Generated an image in 10.38 (prep) and 5.02 (gen) seconds
08:30:31.346 [Info] Generated an image in 10.30 (prep) and 5.34 (gen) seconds
08:30:36.436 [Info] Generated an image in 10.34 (prep) and 5.08 (gen) seconds

[mcmonkey4eva]

Prep time is the pre-handling that overlaps with other generations. Gen time is the time in which resources were locked to this one generation (this is why the first gen has a slightly longer gen time, resources get locked while it's still loading some things).

(Note for the most part "resources are locked" essentially means, ComfyUI is working on the generation. SwarmUI itself operates in parallel, but when it's put through Comfy to use the GPU, Comfy processes linearly. Most of the prep time is spent waiting in Comfy's queue, but a portion of it is the multithreaded processing of generating workflows and anything like that).

it/sec data isn't tracked atm, you can post an Issue to request that. You can however already view it in logs by setting log level to Debug (though of course it gets quite spammy).