chore: Improve logging format for debugging OOM issues (#29330)

Fixes #29114

<!-- This is an auto-generated comment: release notes by coderabbit.ai
-->
## Summary by CodeRabbit

- **New Features**
  - Enhanced logging capabilities for better performance insights.

- **Improvements**
- Increased the number of log file backups to ensure more historical
data is preserved.

- **Documentation**
- Updated internal documentation to reflect new logging and performance
monitoring features.
<!-- end of auto-generated comment: release notes by coderabbit.ai -->
This commit is contained in:
Rajat Agrawal 2023-12-05 19:05:22 +05:30 committed by GitHub
parent 160871bd31
commit 81bebcd914
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 68 additions and 10 deletions

View File

@ -41,6 +41,12 @@
</dependencyManagement> </dependencyManagement>
<dependencies> <dependencies>
<dependency>
<groupId>io.projectreactor</groupId>
<artifactId>reactor-tools</artifactId>
<version>3.6.0</version>
<classifier>original</classifier>
</dependency>
<dependency> <dependency>
<groupId>io.opentelemetry</groupId> <groupId>io.opentelemetry</groupId>
<artifactId>opentelemetry-api</artifactId> <artifactId>opentelemetry-api</artifactId>

View File

@ -4,6 +4,7 @@ import io.micrometer.observation.ObservationRegistry;
import io.micrometer.observation.aop.ObservedAspect; import io.micrometer.observation.aop.ObservedAspect;
import io.opentelemetry.api.OpenTelemetry; import io.opentelemetry.api.OpenTelemetry;
import io.opentelemetry.sdk.autoconfigure.AutoConfiguredOpenTelemetrySdk; import io.opentelemetry.sdk.autoconfigure.AutoConfiguredOpenTelemetrySdk;
import lombok.extern.slf4j.Slf4j;
import org.apache.commons.lang3.StringUtils; import org.apache.commons.lang3.StringUtils;
import org.springframework.boot.Banner; import org.springframework.boot.Banner;
import org.springframework.boot.autoconfigure.SpringBootApplication; import org.springframework.boot.autoconfigure.SpringBootApplication;
@ -11,14 +12,26 @@ import org.springframework.boot.autoconfigure.condition.ConditionalOnExpression;
import org.springframework.boot.builder.SpringApplicationBuilder; import org.springframework.boot.builder.SpringApplicationBuilder;
import org.springframework.context.annotation.Bean; import org.springframework.context.annotation.Bean;
import org.springframework.scheduling.annotation.EnableScheduling; import org.springframework.scheduling.annotation.EnableScheduling;
import reactor.tools.agent.ReactorDebugAgent;
import static com.appsmith.server.constants.EnvVariables.APPSMITH_NEW_RELIC_ACCOUNT_ENABLE; import static com.appsmith.server.constants.EnvVariables.APPSMITH_NEW_RELIC_ACCOUNT_ENABLE;
import static com.appsmith.server.constants.EnvVariables.APPSMITH_VERBOSE_LOGGING_ENABLED;
@SpringBootApplication @SpringBootApplication
@EnableScheduling @EnableScheduling
@Slf4j
public class ServerApplication { public class ServerApplication {
public static void main(String[] args) { public static void main(String[] args) {
String loggingEnabled = System.getenv(String.valueOf(APPSMITH_VERBOSE_LOGGING_ENABLED));
if ("true".equalsIgnoreCase(loggingEnabled)) {
log.info("Enabling Reactor Debug Agent enabled");
ReactorDebugAgent.init();
} else {
log.info("Reactor Debug Agent not enabled");
}
new SpringApplicationBuilder(ServerApplication.class) new SpringApplicationBuilder(ServerApplication.class)
.bannerMode(Banner.Mode.OFF) .bannerMode(Banner.Mode.OFF)
.run(args); .run(args);

View File

@ -1,5 +1,6 @@
package com.appsmith.server.performancelogging; package com.appsmith.server.performancelogging;
import io.micrometer.common.KeyValue;
import io.micrometer.observation.Observation; import io.micrometer.observation.Observation;
import io.micrometer.observation.Observation.Context; import io.micrometer.observation.Observation.Context;
import io.micrometer.observation.ObservationHandler; import io.micrometer.observation.ObservationHandler;
@ -7,13 +8,44 @@ import lombok.extern.slf4j.Slf4j;
import org.springframework.boot.autoconfigure.condition.ConditionalOnExpression; import org.springframework.boot.autoconfigure.condition.ConditionalOnExpression;
import org.springframework.stereotype.Component; import org.springframework.stereotype.Component;
import java.lang.management.ManagementFactory;
import java.lang.management.MemoryMXBean;
@Component @Component
@Slf4j @Slf4j
@ConditionalOnExpression("${logging.verbose.enabled}") @ConditionalOnExpression("${logging.verbose.enabled}")
class PerformanceLoggingHandler implements ObservationHandler<Observation.Context> { class PerformanceLoggingHandler implements ObservationHandler<Observation.Context> {
@Override @Override
public void onStart(Context context) { public void onStart(Context context) {
if (needsLogStatement(context)) {
context.put("executionTime", System.currentTimeMillis()); context.put("executionTime", System.currentTimeMillis());
KeyValue url = context.getHighCardinalityKeyValue("http.url");
String urlName = url == null ? "null" : url.getValue();
log.info("Execution Started : {}, Context : {}, {}", context.getName(), urlName, memoryFootprint());
}
}
private String memoryFootprint() {
MemoryMXBean memoryMXBean = ManagementFactory.getMemoryMXBean();
return String.format(
"Initial memory: %.2f GB, Used heap memory: %.2f GB, Max heap memory: %.2f GB, Committed memory: %.2f GB",
(double) memoryMXBean.getHeapMemoryUsage().getInit() / 1073741824,
(double) memoryMXBean.getHeapMemoryUsage().getUsed() / 1073741824,
(double) memoryMXBean.getHeapMemoryUsage().getMax() / 1073741824,
(double) memoryMXBean.getHeapMemoryUsage().getCommitted() / 1073741824);
}
private Boolean needsLogStatement(Context context) {
String name = context.getName();
if (name.equals("spring.security.authorizations")
|| name.equals("spring.security.filterchains")
|| name.equals("spring.security.http.secured.requests")) {
return false;
} else {
return true;
}
} }
@Override @Override
@ -23,13 +55,20 @@ class PerformanceLoggingHandler implements ObservationHandler<Observation.Contex
@Override @Override
public void onStop(Context context) { public void onStop(Context context) {
if (needsLogStatement(context)) {
long startTime = context.getOrDefault("executionTime", 0L); long startTime = context.getOrDefault("executionTime", 0L);
long executionTime = System.currentTimeMillis() - startTime; long executionTime = System.currentTimeMillis() - startTime;
KeyValue url = context.getHighCardinalityKeyValue("http.url");
String urlName = url == null ? "null" : url.getValue();
log.info( log.info(
"Execution Complete: {} | Total Time Taken: {} ms | Context: {}", "Execution Complete: {} | Total Time Taken: {} ms | Context: {}, {}",
context.getName(), context.getName(),
executionTime, executionTime,
context.toString()); urlName,
memoryFootprint());
}
} }
@Override @Override

View File

@ -10,7 +10,7 @@ stdout_logfile=/appsmith-stacks/logs/%(program_name)s/%(program_name)s-%(ENV_HOS
redirect_stderr=true redirect_stderr=true
stdout_logfile_maxbytes=10MB stdout_logfile_maxbytes=10MB
stderr_logfile_maxbytes=10MB stderr_logfile_maxbytes=10MB
stdout_logfile_backups=2 stdout_logfile_backups=10
stderr_logfile_backups=2 stderr_logfile_backups=10
stdout_events_enabled=true stdout_events_enabled=true
stderr_events_enabled=true stderr_events_enabled=true