azure-functions-host
azure-functions-host copied to clipboard
Azure
Performance: Cache ILogger on FunctionDesciptor
Part of #7908. Cache the logger on the FunctionDescriptor to avoid the .CreateLogger() call every invocation.
Internally, .CreateLogger() (specifically the string variable) has a lock which we pile up on under load and we can avoid both the lock and the service fetch here. Since FunctionDescriptors are re-created with each JobHost, memoizing the logger like this should be okay and change on any host change as we want.
Issue describing the changes in this PR
Resolves part of #7908
Pull request checklist
- [x] My changes do not require documentation changes
- [ ] Otherwise: Documentation issue linked to PR
- [x] My changes should not be added to the release notes for the next release
- [ ] Otherwise: I've added my notes to
release_notes.md
- [ ] Otherwise: I've added my notes to
- [x] My changes do not need to be backported to a previous version
- [ ] Otherwise: Backport tracked by issue/PR #issue_or_pr
- [ ] I have added all required tests (Unit tests, E2E tests)
Crank comparison
| application | dev | fd-logger | |
|---|---|---|---|
| CPU Usage (%) | 7 | 7 | 0.00% |
| Cores usage (%) | 201 | 201 | 0.00% |
| Working Set (MB) | 378 | 382 | +1.06% |
| Private Memory (MB) | 1,181 | 1,199 | +1.52% |
| Build Time (ms) | 15,235 | 17,833 | +17.05% |
| Start Time (ms) | 4,757 | 4,759 | +0.04% |
| Published Size (KB) | 674,605 | 674,605 | 0.00% |
| .NET Core SDK Version | 6.0.100 | 6.0.100 | |
| Max CPU Usage (%) | 99 | 99 | 0.00% |
| Max Working Set (MB) | 396 | 400 | +1.01% |
| Max GC Heap Size (MB) | 145 | 152 | +4.83% |
| Size of committed memory by the GC (MB) | 207 | 225 | +8.70% |
| Max Number of Gen 0 GCs / sec | 13.00 | 13.00 | 0.00% |
| Max Number of Gen 1 GCs / sec | 5.00 | 4.00 | -20.00% |
| Max Number of Gen 2 GCs / sec | 1.00 | 1.00 | 0.00% |
| Max Time in GC (%) | 6.00 | 7.00 | +16.67% |
| Max Gen 0 Size (B) | 92,442,184 | 32,369,448 | -64.98% |
| Max Gen 1 Size (B) | 11,112,344 | 9,449,160 | -14.97% |
| Max Gen 2 Size (B) | 29,196,432 | 27,484,952 | -5.86% |
| Max LOH Size (B) | 9,714,720 | 11,418,936 | +17.54% |
| Max Allocation Rate (B/sec) | 334,226,264 | 340,185,376 | +1.78% |
| Max GC Heap Fragmentation | 83 | 68 | -17.46% |
| # of Assemblies Loaded | 201 | 201 | 0.00% |
| Max Exceptions (#/s) | 258 | 252 | -2.33% |
| Max Lock Contention (#/s) | 109 | 101 | -7.34% |
| Max ThreadPool Threads Count | 29 | 32 | +10.34% |
| Max ThreadPool Queue Length | 92 | 92 | 0.00% |
| Max ThreadPool Items (#/s) | 36,134 | 39,213 | +8.52% |
| Max Active Timers | 85 | 95 | +11.76% |
| IL Jitted (B) | 1,054,396 | 1,055,449 | +0.10% |
| Methods Jitted | 10,879 | 10,887 | +0.07% |
| Avg Allocation Rate (B/sec) | 303,164,832 | 295,241,931 | -2.61% |
| 90th Allocation Rate (B/sec) | 333,317,216 | 328,697,416 | -1.39% |
| load | dev | fd-logger | |
|---|---|---|---|
| CPU Usage (%) | 1 | 1 | 0.00% |
| Cores usage (%) | 37 | 39 | +5.41% |
| Working Set (MB) | 38 | 37 | -2.63% |
| Private Memory (MB) | 357 | 357 | 0.00% |
| Start Time (ms) | 0 | 0 | |
| First Request (ms) | 338 | 344 | +1.78% |
| Requests/sec | 8,082 | 8,467 | +4.76% |
| Requests | 485,330 | 508,824 | +4.84% |
| Mean latency (ms) | 13.76 | 13.10 | -4.80% |
| Max latency (ms) | 205.02 | 169.65 | -17.25% |
| Bad responses | 0 | 0 | |
| Socket errors | 0 | 0 | |
| Read throughput (MB/s) | 1.24 | 1.30 | +4.84% |
| Latency 50th (ms) | 10.00 | 9.57 | -4.30% |
| Latency 75th (ms) | 15.87 | 15.12 | -4.73% |
| Latency 90th (ms) | 27.73 | 26.23 | -5.41% |
| Latency 99th (ms) | 62.69 | 59.60 | -4.93% |
Note I'm not checking the unit test box because I'm not sure if we have a reliable way to test after-reloading-the-host to make sure the ILogger reference on the descriptor changes. IMO, this would be a good test to add but I could use some guidance on the best place for that.
Tagging @fabiocav & @mathewc for a second pass, I think your comments were addressed?
This pull request has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 7 days. It will be closed if no further activity occurs within 7 days of this comment.
