Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

API-26059 Log durations of some sidekiq jobs #12474

Merged
merged 0 commits into from
Apr 27, 2023

Conversation

caseywilliams
Copy link
Contributor

Summary

  • Since the move to EKS, sidekiq jobs should be running in less than 2 minutes, ideally within 1 minute.
  • To facilitate refactoring for this requirement, this adds a new piece of sidekiq middleware which logs the duration of sidekiq jobs in the AppealsApi, VAForms, and VBADocuments APIs.
  • This middlware will only be loaded if the appeals_api_sidekiq_job_duration_logging flipper flag is turned on.
    • This flipper flag (and the middleware itself) can be removed once we have an idea of how long each job generally takes

Related issue(s)

Testing done

  • So far, I've just tested this in the rails console by running a few jobs via perform_async and then running the middleware manually.
  • I put this behind a feature flag, since this manual testing may not be sufficient - I will be trying this in the lower environments before enabling it in production.

What areas of the site does it impact?

Loads middleware for sidekiq that only affects workers from the AppealsAPI module, the VAForms module, and the benefits intake (VBADocuments) module

Acceptance criteria

  • I fixed|updated|added unit tests and integration tests for each feature (if applicable).
  • No error nor warning in the console.
  • Events are being sent to the appropriate logging solution
  • Documentation has been updated (link to documentation)
  • No sensitive information (i.e. PII/credentials/internal URLs/etc.) is captured in logging, hardcoded, or specs
  • Feature/bug has a monitor built into Datadog or Grafana (if applicable)
  • If app impacted requires authentication, did you login to a local build and verify all authenticated routes work as expected
  • I added a screenshot of the developed feature

@caseywilliams caseywilliams added Lighthouse lighthouse appeals Lighthouse API appeals benefits-intake Lighthouse Benefits Intake API banana-peels Lighthouse Banana Peels Team labels Apr 24, 2023
@caseywilliams caseywilliams requested review from a team as code owners April 24, 2023 23:37
@caseywilliams caseywilliams force-pushed the API-26059/sidekiq-duration-logging branch from e4df875 to 6892653 Compare April 24, 2023 23:38
@va-vsp-bot va-vsp-bot requested a deployment to API-26059/sidekiq-duration-logging/main/main April 24, 2023 23:39 In progress
@va-vfs-bot va-vfs-bot temporarily deployed to API-26059/sidekiq-duration-logging/main/main April 24, 2023 23:39 Inactive
mathisto
mathisto previously approved these changes Apr 25, 2023
Copy link
Contributor

@mathisto mathisto left a comment

Choose a reason for hiding this comment

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

Yo, this is slick, low friction, and efficient. NOICE.

@caseywilliams caseywilliams force-pushed the API-26059/sidekiq-duration-logging branch from 6892653 to 7e6bfbb Compare April 25, 2023 17:47
@va-vsp-bot va-vsp-bot requested a deployment to API-26059/sidekiq-duration-logging/main/main April 25, 2023 17:48 In progress
@va-vfs-bot va-vfs-bot temporarily deployed to API-26059/sidekiq-duration-logging/main/main April 25, 2023 17:48 Inactive
config/initializers/sidekiq.rb Outdated Show resolved Hide resolved
Rails.logger.info "Sidekiq job #{worker.class.name} in #{elapsed_time.round} seconds"

module_name = worker.class.name.split('::').first.underscore
@statsd.timing("#{module_name}.sidekiq_job.duration", elapsed_time.round)
Copy link
Contributor

@cilestin cilestin Apr 25, 2023

Choose a reason for hiding this comment

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

How are we to tell which job has which durations within datadog, if we're only grabbing the module name? Shouldn't we also grab the actual class that runs the job?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

As I was refactoring this, I started second guessing whether we should be adding to datadog at all yet - we already have datadog's sidekiq middleware set up here, and it seems like it reports very extensive information. Since none of us is able to actually see datadog yet, I was thinking it might make sense to wait to send data there until we've reviewed what's already being collected - any opinions on that?

Copy link
Contributor

Choose a reason for hiding this comment

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

Do we know anyone with read access who could peek for us?

Copy link
Contributor

Choose a reason for hiding this comment

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

manual datadog duration logging isn't necessary :)

Screenshot 2023-04-26 at 15 23 21

Copy link
Contributor

Choose a reason for hiding this comment

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

With the fact that we're getting automatic perform duration logging w/ DataDog - do we actually need this separate logging into rails logs?

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'd much rather just look at datadog for this information - if we have a pathway to doing that and it's acceptable to wait to get this information until then, I'm happy to close this

Copy link
Contributor

Choose a reason for hiding this comment

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

I think it was added as a stopgap since we don't have DataDog access yet.

Copy link
Contributor

Choose a reason for hiding this comment

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

It also looks like not all of our jobs are being captured by DataDog, so let's keep this in for now until we know that all our jobs are registered.

@caseywilliams caseywilliams force-pushed the API-26059/sidekiq-duration-logging branch from 7e6bfbb to 6679a85 Compare April 26, 2023 15:59
@va-vsp-bot va-vsp-bot requested a deployment to API-26059/sidekiq-duration-logging/main/main April 26, 2023 16:00 In progress
@va-vfs-bot va-vfs-bot temporarily deployed to API-26059/sidekiq-duration-logging/main/main April 26, 2023 16:02 Inactive
@caseywilliams caseywilliams force-pushed the API-26059/sidekiq-duration-logging branch from 6679a85 to 6a5f47a Compare April 26, 2023 16:05
@va-vsp-bot va-vsp-bot requested a deployment to API-26059/sidekiq-duration-logging/main/main April 26, 2023 16:05 In progress
@va-vfs-bot va-vfs-bot temporarily deployed to API-26059/sidekiq-duration-logging/main/main April 26, 2023 16:19 Inactive
@caseywilliams caseywilliams force-pushed the API-26059/sidekiq-duration-logging branch from 6a5f47a to 60b067a Compare April 26, 2023 17:16
@va-vsp-bot va-vsp-bot requested a deployment to API-26059/sidekiq-duration-logging/main/main April 26, 2023 17:17 In progress
@va-vfs-bot va-vfs-bot temporarily deployed to API-26059/sidekiq-duration-logging/main/main April 26, 2023 17:19 Inactive
@caseywilliams caseywilliams force-pushed the API-26059/sidekiq-duration-logging branch from 60b067a to b16bf00 Compare April 26, 2023 18:07
@va-vsp-bot va-vsp-bot requested a deployment to API-26059/sidekiq-duration-logging/main/main April 26, 2023 18:08 In progress
@va-vfs-bot va-vfs-bot temporarily deployed to API-26059/sidekiq-duration-logging/main/main April 26, 2023 18:08 Inactive
@caseywilliams caseywilliams force-pushed the API-26059/sidekiq-duration-logging branch from b16bf00 to b650864 Compare April 26, 2023 19:02
@va-vsp-bot va-vsp-bot requested a deployment to API-26059/sidekiq-duration-logging/main/main April 26, 2023 19:03 In progress
@va-vfs-bot va-vfs-bot temporarily deployed to API-26059/sidekiq-duration-logging/main/main April 26, 2023 19:08 Inactive
config/features.yml Outdated Show resolved Hide resolved
@caseywilliams caseywilliams force-pushed the API-26059/sidekiq-duration-logging branch from b650864 to c577dc4 Compare April 27, 2023 16:52
@va-vsp-bot va-vsp-bot requested a deployment to API-26059/sidekiq-duration-logging/main/main April 27, 2023 16:52 In progress
@va-vfs-bot va-vfs-bot temporarily deployed to API-26059/sidekiq-duration-logging/main/main April 27, 2023 16:53 Inactive
@caseywilliams caseywilliams force-pushed the API-26059/sidekiq-duration-logging branch from c577dc4 to ab8547c Compare April 27, 2023 18:39
@va-vsp-bot va-vsp-bot requested a deployment to API-26059/sidekiq-duration-logging/main/main April 27, 2023 18:39 In progress
@va-vfs-bot va-vfs-bot temporarily deployed to API-26059/sidekiq-duration-logging/main/main April 27, 2023 18:48 Inactive
@cilestin cilestin merged commit 2a0bead into master Apr 27, 2023
@cilestin cilestin deleted the API-26059/sidekiq-duration-logging branch April 27, 2023 21:50
caseywilliams added a commit that referenced this pull request May 31, 2023
ryan-mcneil pushed a commit that referenced this pull request Dec 11, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
appeals Lighthouse API appeals banana-peels Lighthouse Banana Peels Team benefits-intake Lighthouse Benefits Intake API console-services-review Lighthouse lighthouse
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants