Building imgplex: part 7

This is a series of posts on building imgplex, best read in order:
Part 1 - The why, what, and how of imgplex
Part 2 - Getting things up and running
Part 3 - The node definition system
Part 4 - Executing the node graph, making it fast
Part 5 - Two graphs in one
Part 6 - Multiple inputs and outputs, processing images as sets
Part 7 - Profiling and Optimization

Profiling before optimizing

As a technical artist, profiling and instrumentation are very commonly used in my workflow. Visual pipelines can become expensive in ways that are difficult to predict just by looking at the graph. A slow operation may come from image processing, but it can just as easily come from process startup, filesystem access, metadata reads, temporary files, cache invalidation, or work blocking Electron’s main thread. Without measurements, all of those problems look the same: the tool simply feels slow.

I took the same approach with imgplex. The first version of the profiling system was little more than a collection of timers around whichever function I happened to be investigating. Even that basic instrumentation quickly started exposing bottlenecks that I would not have found by looking at the ImageMagick commands alone, so I replaced the temporary measurements with a reusable performance collector.

Part 4 covered the largest optimizations that came out of that work, including reducing ImageMagick process launches, avoiding unnecessary image reads, reusing execution plans, and changing how intermediate files were handled. This post focuses on the instrumentation itself and on the less obvious problems it uncovered after the first optimization pass.

Measuring the pipeline

Performance timers can be enabled from Debug → Enable Performance Timers. Once enabled, imgplex records the major stages of every batch rather than treating the entire workflow as one operation.

The batch report includes pipeline setup time, the delay before the first image begins processing, time spent inside ImageMagick, output-file checks, final copies, and the total duration of the run. It also records per-image statistics such as the average, minimum, maximum, and 95th-percentile processing time, along with the slowest file in the batch.

The 95th percentile turned out to be more useful than the average on its own. A workflow could have a reasonable average while a handful of large or unusual images took several times longer than everything else. Listing the slowest filename made those cases much easier to investigate because I could compare its dimensions, format, workflow path, and ImageMagick timings with the rest of the batch.

The resulting report is printed to the development console and written to perf.log in the output directory. Keeping the report beside the generated files also makes it easier to compare several runs of the same workflow without relying on values copied from the console.

Import performance is measured separately because it uses a different set of systems. Each imported file is classified according to whether it was loaded entirely from cache, handled through the faster metadata path, or processed through the slower ImageMagick path. The report records how many files used each route and how much time was spent reading metadata, generating thumbnails, and waiting for ImageMagick.

Before that breakdown existed, several unrelated problems all appeared as “folder import is slow.” A warm cache behaves very differently from a cold one, and a folder containing mostly PNG or JPEG files follows a different path from one containing hundreds of PSD files. Separating those measurements stopped me from optimizing whichever part merely looked suspicious and showed which path was actually responsible.

Capturing ImageMagick diagnostics

When the performance timers are active, imgplex can also capture ImageMagick’s verbose output for batch operations. This adds information such as source format, image dimensions, colorspace, file size, and ImageMagick’s reported elapsed time to the same log as the application-level measurements.

Having both values is useful because the time measured around a process is not necessarily the same as the time ImageMagick spends transforming pixels. The outer measurement also includes process creation, argument preparation, filesystem activity, and the transfer of results back to imgplex. Comparing the two helped identify cases where the image operation itself was quick but the complete process was still expensive.

The verbose capture exposed a small Windows-specific problem. I originally placed the -verbose argument alongside the per-image options, but some ImageMagick builds silently ignored it in that position. Moving the flag before the input file, where ImageMagick treats it as a global option, made the output consistent across the builds I tested.

The timing summary and verbose output were also initially appended to perf.log in separate operations. On Windows, those writes could compete for the same file handle, leaving the report incomplete. They are now combined into one append operation. Neither problem affected the processed images, so without checking the instrumentation itself, both would have been easy to miss.

What the measurements exposed

Once the timing system was available, the major pipeline bottlenecks became much easier to identify. Process creation was often more expensive than the individual image operation being performed. Some property nodes accidentally caused multiple ImageMagick processes to be launched for every file, and temporary images were being compressed even though they would immediately be read and deleted. Import was also invoking ImageMagick for information that could be read directly from common image headers.

Those discoveries led to the larger changes described in Part 4. After they were fixed, profiling shifted toward problems that appeared only with larger graphs, overlapping operations, long-running sessions, or folders containing several thousand files.

The remaining bottlenecks were less dramatic, but they were still worth addressing. They also tended to involve assumptions in imgplex itself rather than the speed of ImageMagick.

More precise preview invalidation

The preview pipeline caches the output of individual nodes. When a node changes, its cached result and the results of anything depending on it have to be discarded before the next preview can run.

My first implementation used the graph’s topological order to decide what should be invalidated. The changed node and everything appearing after it in the sorted list were removed from the cache. That was safe, but it was broader than necessary because topological order only guarantees a valid execution sequence. It does not mean that every later node depends on every earlier one.

The problem became visible in graphs with several parallel branches. Editing one branch caused nodes in unrelated branches to execute again simply because they appeared later in the sorted order. The preview was still correct, but the timing data showed work happening in parts of the graph that had not changed.

The current implementation follows outgoing connections from the edited node and performs a forward traversal through its actual descendants. Only the changed node and nodes reachable from it are invalidated. Upstream nodes and sibling branches keep their cached results.

This was a useful correction to the original cache design. Execution order and dependency are related, but treating them as interchangeable caused the cache to discard more work than the graph required.

Keeping thread limits local

imgplex can have several kinds of ImageMagick work active at the same time. A batch might be running while the user changes a preview or imports another folder, and each of those systems may launch its own processes.

To prevent CPU oversubscription, each ImageMagick process receives a thread limit. My first implementation applied that limit by temporarily changing process.env.MAGICK_THREAD_LIMIT immediately before starting a process and restoring the old value afterward.

That appeared to work when operations happened one at a time. It became unreliable when their timings overlapped because process.env is shared by the entire Electron main process. A preview could change the value while a batch was preparing its next process, and an import could replace it again before either operation restored the previous setting.

The thread limit is now added to the environment passed directly to each spawn call. Every ImageMagick process receives its own value without modifying shared Node.js state. Batch operations can use their calculated thread allowance while thumbnail processes remain limited independently.

This race was difficult to reproduce through isolated tests because each system behaved correctly on its own. It only appeared when separate workloads happened to launch processes at nearly the same time. The process timings and structured logs made those overlaps visible.

Keeping the main process responsive

Not every performance issue was inside the image-processing pipeline. Electron’s main process also handles IPC, application windows, menus, secondary windows, and much of the filesystem work used by imgplex. A long synchronous operation there can make the entire application feel unresponsive, even if the renderer is not doing anything expensive.

Folder scanning originally used synchronous directory functions. The pause was difficult to notice with a small folder, but recursively scanning a large directory tree could keep the main process busy until every subdirectory had been visited. During that time, unrelated IPC requests also had to wait.

The scanner now uses the asynchronous fs.promises APIs. It still visits the same directories and inspects the same files, so this change does not necessarily make the filesystem complete its work faster. The difference is that the main process yields while waiting for each operation, allowing other application work to continue.

That distinction became more important as imgplex gained cancellation, live logging, secondary windows, multiple Input nodes, and overlapping imports and previews. The main process was no longer responsible for a single operation at a time, so keeping its event loop available became part of the performance work.

Cleaning temporary files and caches

imgplex writes several kinds of temporary data, including batch intermediates, preview files, thumbnails, and cached metadata. A normal shutdown removes the short-lived batch files, but a crash or forced exit can leave some of them behind.

The application now scans its temporary directory during startup and removes orphaned batch intermediates from previous sessions. Thumbnail and preview files are handled differently because keeping recent ones is useful when reopening the same folders. Instead of removing the whole cache, imgplex deletes cached files that have not been modified for more than 14 days.

The first cleanup implementation ran as part of the startup sequence. As the cache grew, that risked delaying the application window, so the sweep was changed to run asynchronously. Cleanup is treated as best-effort work: a missing, locked, or already-deleted file is logged but does not stop the application from opening.

This was not a problem that appeared during the first few weeks of development because the cache had not existed long enough to grow. It became visible only after using the application across longer sessions and repeatedly opening different image folders.

Structured application logging

The performance report is intended for profiling a particular run, but imgplex also has a general logging system for understanding what happens throughout a session. The logger records ImageMagick launches, batch processing, imports, thumbnail generation, previews, node-definition reloads, IPC handlers, and application errors.

For each ImageMagick process, the log stores a shortened version of its arguments, its duration, and whether it completed successfully. Failed commands also include the exit code and a limited section of their error output. This provides enough context to identify the operation without allowing one large command or error message to overwhelm the log.

A live log viewer receives new entries from the main process as they are written. This has been particularly useful when investigating a slow or failed workflow in a packaged build, where there is no development terminal visible.

The same entries are appended to a persistent imgplex.log file, so the information remains available after the application has been closed. The in-memory history used by the viewer is capped at 1,000 entries. Once that limit is reached, the oldest entries are removed from the live list while new entries continue to be written to disk.

Without the cap, leaving imgplex open through a long session containing many previews, imports, and batch operations could allow the log array to grow indefinitely. The persistent file retains the full session history, while the viewer only keeps the entries most likely to be relevant to the current problem.

The logging system has also made user reports more useful. Instead of relying only on a description of what happened, I can inspect which ImageMagick command ran, how long it took, and what error it returned on that machine.

Instrumentation as part of development

The performance tools were not added after imgplex was finished. They became part of how I developed the pipeline.

That approach comes directly from my technical-art background. When working with shaders, VFX, procedural tools, or content pipelines, knowing that something is slow is only the start. The useful questions are which stage is slow, what input triggers it, and how many times that stage runs.

A timer around the complete workflow might show that a batch took two minutes, but it would not reveal that nearly all of that time came from reading one property that was already available from the filesystem. A preview timer might show that an edit was slow without revealing that unrelated branches were being invalidated. One overall import time would not distinguish cached files from native metadata reads or files that required ImageMagick.

Adding instrumentation early meant I could refine the measurements as the application evolved. Features such as multiple inputs, image sets, and typed outputs could be compared with earlier builds instead of relying entirely on whether they felt faster or slower.

It also changed how I approached optimization. The first performance pass removed the largest repeated costs. Later profiling corrected assumptions that only failed under more complicated conditions: sorted order was not the same as dependency, shared environment variables were unsafe across overlapping operations, synchronous scans were acceptable only while test folders remained small, and a cache that seemed harmless eventually needed an expiry policy.

None of those implementations was obviously broken in the first version. They became problems as imgplex was used with larger folders, more complex graphs, overlapping workloads, and longer sessions. Profiling and logging made those problems measurable and helped verify that each fix improved the intended path without quietly making another one worse.

That has been the most useful result of adding instrumentation early. Performance work became part of normal development rather than a cleanup stage left until the end.