Skip to content

NIFI-8405: Added debug logging around how long it takes to establish …#4983

Closed
markap14 wants to merge 2 commits intoapache:mainfrom
markap14:NIFI-8405
Closed

NIFI-8405: Added debug logging around how long it takes to establish …#4983
markap14 wants to merge 2 commits intoapache:mainfrom
markap14:NIFI-8405

Conversation

@markap14
Copy link
Contributor

@markap14 markap14 commented Apr 8, 2021

…connections/query dns/read and write headers and body when replication requests; added additional timing around Ranger audits and authorizations and monitoring of long-running tasks because those run often and frequently show up in the logs at the same time as the long requests

Thank you for submitting a contribution to Apache NiFi.

Please provide a short description of the PR here:

Description of PR

Enables X functionality; fixes bug NIFI-YYYY.

In order to streamline the review of the contribution we ask you
to ensure the following steps have been taken:

For all changes:

  • Is there a JIRA ticket associated with this PR? Is it referenced
    in the commit message?

  • Does your PR title start with NIFI-XXXX where XXXX is the JIRA number you are trying to resolve? Pay particular attention to the hyphen "-" character.

  • Has your PR been rebased against the latest commit within the target branch (typically main)?

  • Is your initial contribution a single, squashed commit? Additional commits in response to PR reviewer feedback should be made on this branch and pushed to allow change tracking. Do not squash or use --force when pushing to allow for clean monitoring of changes.

For code changes:

  • Have you ensured that the full suite of tests is executed via mvn -Pcontrib-check clean install at the root nifi folder?
  • Have you written or updated unit tests to verify your changes?
  • Have you verified that the full build is successful on JDK 8?
  • Have you verified that the full build is successful on JDK 11?
  • If adding new dependencies to the code, are these dependencies licensed in a way that is compatible for inclusion under ASF 2.0?
  • If applicable, have you updated the LICENSE file, including the main LICENSE file under nifi-assembly?
  • If applicable, have you updated the NOTICE file, including the main NOTICE file found under nifi-assembly?
  • If adding new Properties, have you added .displayName in addition to .name (programmatic access) for each of the new properties?

For documentation related changes:

  • Have you ensured that format looks appropriate for the output in which it is rendered?

Note:

Please ensure that once the PR is submitted, you check GitHub Actions CI for build issues and submit an update to your PR as soon as possible.

…connections/query dns/read and write headers and body when replication requests; added additional timing around Ranger audits and authorizations and monitoring of long-running tasks because those run often and frequently show up in the logs at the same time as the long requests
okHttpClientBuilder.followRedirects(true);
final int connectionPoolSize = properties.getClusterNodeMaxConcurrentRequests();
okHttpClientBuilder.connectionPool(new ConnectionPool(connectionPoolSize, 5, TimeUnit.MINUTES));
okHttpClientBuilder.eventListener(new RequestReplicationEventListener());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of introducing the custom RequestReplicationEventListener and CallEventListener classes for logging, would the okhttp3.logging.LoggingEventListener class accomplish the same goal?

Introducing the potential for logging events could have performance implications, what do you think about adding check for logger.isDebugEnabled() to control whether or not to add the Event Listener?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I took a look at the LoggingEventListener, but it logs each individual event individually, and since we're always replicating to each node in the cluster, that becomes really difficult to partition out and understand, either programmatically or manually.

I did also consider using a mechanism to avoid the expensive of doing this if logging is not enabled. But since this is done only when we replicate requests across the cluster, that's not terribly frequently and so the overhead is almost nil. We could, in the future, improve it, by checking isDebugEnabled() but I didn't want to cloud the code at this point, given the (little) expense of the operation and how infrequently it's performed. Plus, I can envision improving this in the future to do something like always warn if DNS lookup takes more than 1 second or something like that, even if debug logging is not enabled.


getLogger().info("Active threads: {}; Long running threads: {}", activeThreadCount, longRunningThreadCount);
final long nanos = System.nanoTime() - start;
getLogger().info("Active threads: {}; Long running threads: {}; time to check: {} nanos", activeThreadCount, longRunningThreadCount, NumberFormat.getInstance().format(nanos));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unfortunately, changing this logging statement broke the existing unit test, so some adjustment will be necessary.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

D'oh, thanks!

@exceptionfactory
Copy link
Contributor

Thanks for the responses @markap14, the implementation seems reasonable given the goals described. The unit test update looks good. +1 Merging.

@asfgit asfgit closed this in 14e6dc3 Apr 8, 2021
krisztina-zsihovszki pushed a commit to krisztina-zsihovszki/nifi that referenced this pull request Jun 28, 2022
…connections/query dns/read and write headers and body when replication requests; added additional timing around Ranger audits and authorizations and monitoring of long-running tasks because those run often and frequently show up in the logs at the same time as the long requests

This closes apache#4983

Signed-off-by: David Handermann <exceptionfactory@apache.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants