NIFI-15531 Repositioned log statements to indicate how long map extensions take.

[dan-s1]

Summary

NIFI-15531

Tracking

Please complete the following tracking steps prior to pull request creation.

Issue Tracking

• Apache NiFi Jira issue created

Pull Request Tracking

• Pull Request title starts with Apache NiFi Jira issue number, such as NIFI-00000
• Pull Request commit message starts with Apache NiFi Jira issue number, as such NIFI-00000
• Pull request contains commits signed with a registered key indicating Verified status

Pull Request Formatting

• Pull Request based on current revision of the main branch
• Pull Request refers to a feature branch with one commit containing changes

Verification

Please indicate the verification steps performed prior to pull request creation.

Build

• Build completed using ./mvnw clean install -P contrib-check
  • JDK 21
  • JDK 25

Licensing

• New dependencies are compatible with the Apache License 2.0 according to the License Policy
• New dependencies are documented in applicable LICENSE and NOTICE files

Documentation

• Documentation formatting appears as expected in rendered files

[exceptionfactory]

Thanks for the proposing these additional logs @dan-s1.

On initial review, the new Started log does not seem necessary, it contains no details about the particular extension, and it is duplicative of existing debug logs.

The time calculation for each NAR is something to consider, but it would also produce a lot of additional info messages. This might be something to consider at the debug level.

Is there a particular reason you would like to time this operation?

[dan-s1]

This was added per a coworker's frustration as to what what is happening in that gap of time.

[exceptionfactory]

This was added per a coworker's frustration as to what what is happening in that gap of time.

Thanks @dan-s1. In that case, I'm not sure there is a worthwhile addition.

As mentioned, the existing debug-level logging provides more information if desired. Simply writing more log messages to indicate additional detail is not necessarily the best path forward. If there is a problem with the behavior, that may be worth addressing. The fact that the NAR unpacking described on the Jira issue takes almost 30 seconds is notable, as it seems to indicate either slow decompression or write operations, among some possibilities.

[mosermw]

Adding 2 INFO log messages seems reasonable, if we can identify and describe what NiFi is doing. We do account for "Expanding NAR files" which took 4.873 seconds in the example below. What about the 4.052 seconds after that and before the 117 lines of "Loaded NAR file:"? What is NiFi doing?

2026-01-30 19:46:25,215 INFO [main] org.apache.nifi.nar.NarUnpacker Expanding 117 NAR files started
2026-01-30 19:46:30,088 INFO [main] org.apache.nifi.nar.NarUnpacker Expanded 117 NAR files in 4.873 seconds (4873023800 ns)
2026-01-30 19:46:34,140 INFO [main] org.apache.nifi.nar.NarClassLoaders Loaded NAR file:

Maybe we can do one INFO message with "Loading 117 NAR files", change the 117 "Loaded NAR file" messages to the DEBUG level, and finish up with one INFO message "Loaded 117 NAR files in ??? seconds (??? ns)". For example:

2026-01-30 19:46:25,215 INFO [main] org.apache.nifi.nar.NarUnpacker Expanding 117 NAR files started
2026-01-30 19:46:30,088 INFO [main] org.apache.nifi.nar.NarUnpacker Expanded 117 NAR files in 4.873 seconds (4873023800 ns)
2026-01-30 19:46:30,140 INFO [main] org.apache.nifi.nar.NarUnpacker Loading 117 NAR files started
2026-01-30 19:46:39,140 INFO [main] org.apache.nifi.nar.NarUnpacker Loaded 117 NAR files in 9.000 seconds (9000000000 ns)

[mosermw]

Or, as a completely different idea, move the "Expanded 117 NAR files in 4.873 seconds" INFO message farther down in the unpackNars() method, to include the calls to mapExtension()s and populateExtensionMapping() in the timer?

[exceptionfactory]

@dan-s1 Does the existing debug-level log for each NAR file meet the need described? As mentioned, I don't think it makes sense to introduce more verbose info-level logging for each NAR, and the current state of the PR logging the time spent mapping extensions does not seem needed.

[dan-s1]

The debug messages do not really address the issue and really are not necessary. The main concern was the hang time that occurs after the log message on line 205:
logger.info("Expanded {} NAR files in {} seconds ({} ns)", narFiles.size(), durationSeconds, duration);
which apparently is caused by how long mapExtensions on line 211 takes.

My coworker did suggest perhaps pushing up lines 120-121

final long startTime = System.nanoTime();
logger.info("Expanding {} NAR files started", narFiles.size());

above line 119 if (!narFiles.isEmpty())
(as narFiles will never be empty since there will always be at the minimum the nar files of the framework)
and lines 203-205

final long duration = System.nanoTime() - startTime;
final double durationSeconds = TimeUnit.NANOSECONDS.toMillis(duration) / 1000.0;
logger.info("Expanded {} NAR files in {} seconds ({} ns)", narFiles.size(), durationSeconds, duration);

after line 212 populateExtensionMapping thereby indicating the hang time is attributed/related to the nar expansions.

This does not add any extra logging just places the same logging a few lines later.

[exceptionfactory]

Thanks @dan-s1, moving the existing logging lines as suggested sounds like a good plan, that way it encompasses the totality of the method.