Comments (15)
Hey @drissamri Thanks for opening the issue. I quickly looked at different branches, and its interesting to see this behaviour.
While as far I can see difference between branches, you have not actually used any Powertools logging feature, but rather just changed to use log4j2 instead which you offcourse get as a dependency via logging module from powertools. We actually did a performance test before releasing the module and found log4j2 performing much faster compared to logback/slf4j instead. We in fact specifically tested via lambda-logging itself.
Even if you look at this article on performance benchmark for different logging library we see the same results.
Nevertheless, since you have concrete examples to show the difference, I will be diving a bit deep later this week to check what might be leading to the observation you have in the example above.
from powertools-lambda-java.
After I posted this ticket I tested a few more things and saw a mistake in the implementation too (not too logging itself), if I didn't add the @powertools annotation I must've forgot it on that branch after my tests again.
Going to circle back on the tests results later tonight. There was still a big difference after my last run, but will update the branches so you have a correct view.
from powertools-lambda-java.
There was a bug in the lumigo-cli that made the invocation not complete succesfully, so the invocation timings weren't always correct.
Aha, This makes sense, coz I tried replicating yesterday and found the same issue that function was failing in logs. I spent most of my time figuring out, what i might be doing wrong :D. I just ended up changing lambda function contract to work with String and just measure it based on that in both implementation.
The findings for me were bit similar as well what you have posted above. I still have to dive a bit deep to see why this might be happening.
When it come to warning, I too noticed that and also fixed it by adding:
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-slf4j-impl</artifactId>
<version>${log4j.version}</version>
</dependency>
I will look at your branches and dive a bit more into details some time this week.
from powertools-lambda-java.
FYI: I worked together with Yan and now the measure coldstarts CLI measures both initDuration and duration time.
from powertools-lambda-java.
hi @qtdzz There was some optimizations done before going GA to the logging module, not specifically targeting this specific issue.
from powertools-lambda-java.
There was a bug in the lumigo-cli that made the invocation not complete succesfully, so the invocation timings weren't always correct. Thanks to @theburningmonk that's fixed now.
@pankajagrawal16 I created two branches baseline
(lambda-logging) and powertoolslogging
and updated the full statistics for both in the README.md.
baseline
: p95 of 200 cold start iterations: 1400-1435ms
powertoolslogging
: p95 of 200 cold start iterations: 1990ms
In the powertoolslogging you do get to see these messages, so not sure if they cause for an extra delay:
2020-10-06T00:18:26.585+02:00 | SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
-- | --
| 2020-10-06T00:18:26.585+02:00 | SLF4J: Defaulting to no-operation (NOP) logger implementation
| 2020-10-06T00:18:26.585+02:00 | SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
If I'm still doing anything wrong or if I can help in any way, let me know!
from powertools-lambda-java.
After a discussion with @theburningmonk today, I realized the lumigo-cli only prints out initDuration (Initialization in X-Ray) and not (execution) Duration. This will be changed by him later on.
I don't think it matters for the statistics I posted before since the clear distinction is there in both in the Initialization alone already, but end to end should be measured to make sure one of both is not losing more time during execution.
from powertools-lambda-java.
After a discussion with @theburningmonk today, I realized the lumigo-cli only prints out initDuration (Initialization in X-Ray) and not (execution) Duration. This will be changed by him later on.
I don't think it matters for the statistics I posted before since the clear distinction is there in both in the Initialization alone already, but end to end should be measured to make sure one of both is not losing more time during execution.
Yeah I have been looking at logic of cloudwatch log insights query that the cli executes and I could see just looks for Init time in lambda logs.
I do agree, regardless it gives some indication anyways.
from powertools-lambda-java.
Hi @drissamri and @pankajagrawal16, may I ask if there is any update on this issue? Is it still a problem in v1.5.0? The reported version seems to be in a beta version a while ago. Many thanks!
from powertools-lambda-java.
I went ahead and tried it again with the latest version of the powertools (1.7.1) . I had to add jackson-core
and jackson-annotations
which wasn't the case before? Was it considered to use jackson-jr instead of jackson? (as recommended by docs)
Sadly, the results are worse than before :(
baseline
{
"functionName": "client-service-dev-create-client",
"memorySize": 3008,
"coldStarts": 78,
"min": 1482.33,
"p25": 1579.68,
"median": 1601.91,
"p75": 1636.67,
"p95": 1688.14,
"max": 1730.54,
"stddev": 42.1809
}
powertools:
{
"functionName": "client-service-dev-create-client",
"memorySize": 3008,
"coldStarts": 85,
"min": 2329.65,
"p25": 2399.04,
"median": 2430.01,
"p75": 2542.72,
"p95": 2780.87,
"max": 3133.66,
"stddev": 140.8058
}
from powertools-lambda-java.
Hi @drissamri Thanks for following up on this again.
I have taken some time again today to understand what's going on between different implementations.
Starting with your question on jackson-core and annotation missing. This has not changed. Reason why this is failing in your sample project is because jackson-jr-objects
is bringing inn older version of jackson core with it and that confilcts with latest version of jackson core and log4j2 which needs JacksonFeature and has been added in 2.12.x. So that is why in order to remove this dependency conflict, you might have needed to add those explicitly.
Now for performance with slf4j and logback, we need to compare similar feature set. Which means powertools-loggging by default provides support for structured logging whereas comparison made above is not doing any structured logging.
Therefore, I enabled json logging with logback with lambda-logging and results showed increased latency with cold start as well.
{
"note": "The values include both DURATION as well as INIT DURATION",
"result": [
{
"functionName": "powertools-baseline-dev-create-client",
"memorySize": 3008,
"coldStarts": 78,
"min": 1752.49,
"p25": 1798.27,
"median": 1835.61,
"p75": 1871.94,
"p95": 1950.44,
"max": 2083.6,
"stddev": 55.9915
}
]
}
{
"note": "The values include both DURATION and INIT DURATION",
"result": [
{
"functionName": "powertools-baseline-dev-create-client",
"memorySize": 3008,
"coldStarts": 72,
"min": 1722.84,
"p25": 1798.01,
"median": 1831.7,
"p75": 1865.05,
"p95": 1941.07,
"max": 2031.49,
"stddev": 54.8105
}
]
}
Other aspect is that powertools-logging provides several best practices on top of logging and that will definitely contribute to bit more processing and init time and thus contributing a bit more latency during init. Using jackson-jr
wont be helpful since log4j2 internally using jackson anyways to perform structured logging.
I performed another test on latest powertools and results: (Also note difference in number of cold starts for metrics between powertools and lambda-logging)
{
"note": "The values include both DURATION as well as INIT DURATION",
"result": [
{
"functionName": "powertools-issue-dev-create-client",
"memorySize": 3008,
"coldStarts": 92,
"min": 2122.98,
"p25": 2379.61,
"median": 2411.51,
"p75": 2450.12,
"p95": 2515,
"max": 2659.88,
"stddev": 64.3841
}
]
}
{
"functionName": "powertools-issue-dev-create-client",
"note": "The values include both DURATION as well as INIT DURATION",
"result": [
{
"functionName": "powertools-issue-dev-create-client",
"memorySize": 5120,
"coldStarts": 91,
"min": 2178.07,
"p25": 2264.82,
"median": 2298.19,
"p75": 2396.69,
"p95": 2487.52,
"max": 3056.99,
"stddev": 111.0053
}
]
}
That being said, I will spend some more time in this week to find the possibility of optimising jackson object mapper initialisation for structured logs
from powertools-lambda-java.
Done minor tweaks to logging utility as well #484. Based on comparison and also difference in number of cold starts in metrics, I feel comfortable not doing anything more.
I have had a look at default log4j2 config and it is optimal for the lambda workload already. Users always have ability to configure log4j2 the way they need like using asynchronous logging, etc.
cc @drissamri I will be interested in hearing your thoughts on observations above.
from powertools-lambda-java.
Some improvements shipped in https://github.com/awslabs/aws-lambda-powertools-java/releases/tag/v1.7.2 as well. I will wait for @drissamri thoughts before closing it.
from powertools-lambda-java.
@drissamri Let me know if you have any thoughts on above findings ? Or else i will close this issue for now.
from powertools-lambda-java.
Closing this issue for now.
from powertools-lambda-java.
Related Issues (20)
- Putting metrics fails when POWERTOOLS_METRICS_NAMESPACE is not set HOT 3
- Logging: Trace ID not logged with Java 17 runtime HOT 1
- Feature enhancement: Create a Subsegments for operations handled by Powertools HOT 5
- Logging: print `message` as JSON, instead of wrapping into a string HOT 14
- Exceptions not showing in Traces HOT 1
- RFC: Introduce Version 2
- RFC: Remove support for Java 8 in V2 HOT 7
- Feature enhancement (Logger): automatically intercept Runtime exceptions, and log information HOT 7
- Log level not restored at the end of execution HOT 2
- Support batch secrets retrieval in Parameters module HOT 6
- Maintenance: update jackson and aws-xray-recorder dependencies together HOT 4
- RFC: handle batch messages in parallel in batch module HOT 13
- v2: Example logging configuration needs to be updated HOT 3
- v2 - Params builders do not supply default TransformationManager HOT 1
- bug - v2 - end-to-end tests broken
- AbstractCustomResourceHandler - Unable to send response HOT 2
- LambdaEcsLayout seems to incorrectly serialize the service field HOT 7
- Add support for CRaC
- RFC: support for multi-endpoint HTTP handler Lambda functions HOT 9
- Docs: Add Powertools for AWS Lambda workshop to documentation
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from powertools-lambda-java.