Skip to content

Trunk 6514 performance markers #5663

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.

Sign up for GitHub

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

Open
YO-WHATS-UP2 wants to merge 4 commits into
base: master
Choose a base branch
from
Open

Trunk 6514 performance markers #5663

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
a2ae4a7
TRUNK-6514: Add performance markers to startup logs
YO-WHATS-UP2 Jan 12, 2026
b809a29
minor fixes
YO-WHATS-UP2 Jan 12, 2026
755648f
minor fixes 2
YO-WHATS-UP2 Jan 12, 2026
7fd6772
Move performance marker to OpenmrsConstants and add documentation
YO-WHATS-UP2 Jan 12, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
18 changes: 9 additions & 9 deletions api/src/main/java/org/openmrs/module/ModuleUtil.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -866,7 +866,7 @@ public static AbstractRefreshableApplicationContext refreshApplicationContext(Ab
for (Module module : startedModules) {
try {
if (module.getModuleActivator() != null) {
log.debug("Run module willRefreshContext: {}", module.getModuleId());
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Run module willRefreshContext: {}", module.getModuleId());
Thread.currentThread().setContextClassLoader(ModuleFactory.getModuleClassLoader(module));
module.getModuleActivator().willRefreshContext();
}
Expand All @@ -892,8 +892,8 @@ public static AbstractRefreshableApplicationContext refreshApplicationContext(Ab
OpenmrsClassLoader.destroyInstance();
ctx.setClassLoader(OpenmrsClassLoader.getInstance());
Thread.currentThread().setContextClassLoader(OpenmrsClassLoader.getInstance());
log.debug("Refreshing context");

log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Refreshing context");
ServiceContext.getInstance().startRefreshingContext();
try {
ctx.refresh();
Expand All @@ -904,13 +904,13 @@ public static AbstractRefreshableApplicationContext refreshApplicationContext(Ab
finally {
ServiceContext.getInstance().doneRefreshingContext();
}
log.debug("Done refreshing context");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Done refreshing context");

ctx.setClassLoader(OpenmrsClassLoader.getInstance());
Thread.currentThread().setContextClassLoader(OpenmrsClassLoader.getInstance());

OpenmrsClassLoader.restoreState();
log.debug("Startup scheduler");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Startup scheduler");
SchedulerUtil.startup(Context.getRuntimeProperties());

OpenmrsClassLoader.setThreadsToNewClassLoader();
Expand All @@ -934,20 +934,20 @@ public static AbstractRefreshableApplicationContext refreshApplicationContext(Ab
ModuleFactory.passDaemonToken(module);

if (module.getModuleActivator() != null) {
log.debug("Run module contextRefreshed: {}", module.getModuleId());
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Run module contextRefreshed: {}", module.getModuleId());
module.getModuleActivator().contextRefreshed();
try {
//if it is system start up, call the started method for all started modules
if (isOpenmrsStartup) {
log.debug("Run module started: {}", module.getModuleId());
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Run module started: {}", module.getModuleId());
module.getModuleActivator().started();
}
//if refreshing the context after a user started or uploaded a new module
else if (!isOpenmrsStartup && module.equals(startedModule)) {
log.debug("Run module started: {}", module.getModuleId());
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Run module started: {}", module.getModuleId());
module.getModuleActivator().started();
}
log.debug("Done running module started: {}", module.getModuleId());
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Done running module started: {}", module.getModuleId());
}
catch (Error e) {
log.warn("Unable to invoke started() method on the module's activator", e);
Expand Down
9 changes: 9 additions & 0 deletions api/src/main/java/org/openmrs/util/OpenmrsConstants.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,6 +33,8 @@
import org.openmrs.scheduler.SchedulerConstants;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;

import static java.util.Arrays.asList;

Expand All @@ -45,6 +47,13 @@
public final class OpenmrsConstants {

private static final Logger log = LoggerFactory.getLogger(OpenmrsConstants.class);

/**
* Marker used for performance-related log entries.
* To filter log files: grep "performance" openmrs.log
* To find usages in source: Get-ChildItem -Recurse -Filter *.java | Select-String "PERFORMANCE_MARKER"
*/
public static final Marker PERFORMANCE_MARKER = MarkerFactory.getMarker("performance");

public static String KEY_OPENMRS_APPLICATION_DATA_DIRECTORY = "OPENMRS_APPLICATION_DATA_DIRECTORY";

Expand Down
17 changes: 9 additions & 8 deletions web/src/main/java/org/openmrs/module/web/WebModuleUtil.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -65,6 +65,7 @@
import org.openmrs.scheduler.SchedulerService;
import org.openmrs.scheduler.TaskDefinition;
import org.openmrs.util.OpenmrsUtil;
import org.openmrs.util.OpenmrsConstants;
import org.openmrs.util.PrivilegeConstants;
import org.openmrs.web.DispatcherServlet;
import org.openmrs.web.StaticDispatcherServlet;
Expand All @@ -87,7 +88,7 @@ private WebModuleUtil() {
}

private static final Logger log = LoggerFactory.getLogger(WebModuleUtil.class);

private static final Lock SERVLET_LOCK = new ReentrantLock();

private static final Lock FILTERS_LOCK = new ReentrantLock();
Expand Down Expand Up @@ -123,8 +124,8 @@ private WebModuleUtil() {
* @return boolean whether or not the spring context need to be refreshed
*/
public static boolean startModule(Module mod, ServletContext servletContext, boolean delayContextRefresh) {
log.debug("Trying to start module {}", mod);

log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Trying to start module {}", mod);

// only try and start this module if the api started it without a
// problem.
Expand Down Expand Up @@ -314,11 +315,11 @@ public static boolean startModule(Module mod, ServletContext servletContext, boo
// refresh the spring web context to get the just-created xml
// files into it (if we copied an xml file)
if (moduleNeedsContextRefresh && !delayContextRefresh) {
log.debug("Refreshing context for module {}", mod.getModuleId());
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Refreshing context for module {}", mod.getModuleId());

try {
refreshWAC(servletContext, false, mod);
log.debug("Done refreshing context for module {}", mod.getModuleId());
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Done refreshing context for module {}", mod.getModuleId());
}
catch (Exception e) {
String msg = "Unable to refresh the WebApplicationContext";
Expand All @@ -340,9 +341,9 @@ public static boolean startModule(Module mod, ServletContext servletContext, boo
}

// try starting the application context again
log.debug("Refreshing context for module {} (re-trying)", mod.getModuleId());
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Refreshing context for module {} (re-trying)", mod.getModuleId());
refreshWAC(servletContext, false, mod);
log.debug("Done refreshing context for module {} (re-trying)", mod.getModuleId());
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Done refreshing context for module {} (re-trying)", mod.getModuleId());

notifySuperUsersAboutModuleFailure(mod);
}
Expand Down Expand Up @@ -932,7 +933,7 @@ public static XmlWebApplicationContext refreshWAC(ServletContext servletContext,
Module startedModule) {
XmlWebApplicationContext wac = (XmlWebApplicationContext) WebApplicationContextUtils
.getWebApplicationContext(servletContext);
log.debug("Refreshing Web Application Context of class: {}", wac.getClass().getName());
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Refreshing Web Application Context of class: {}", wac.getClass().getName());

if (dispatcherServlet != null) {
dispatcherServlet.stopAndCloseApplicationContext();
Expand Down
22 changes: 11 additions & 11 deletions web/src/main/java/org/openmrs/web/Listener.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -82,7 +82,7 @@
public final class Listener extends ContextLoader implements ServletContextListener, HttpSessionListener {

private static final org.slf4j.Logger log = LoggerFactory.getLogger(Listener.class);

private static boolean runtimePropertiesFound = false;

private static Throwable errorAtStartup = null;
Expand Down Expand Up @@ -247,11 +247,11 @@ public void contextInitialized(ServletContextEvent event) {
* This logic is from ContextLoader.initWebApplicationContext. Copied here instead
* of calling that so that the context is not cached and hence not garbage collected
*/
log.debug("Refreshing WAC");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Refreshing WAC");
XmlWebApplicationContext context = (XmlWebApplicationContext) createWebApplicationContext(servletContext);
configureAndRefreshWebApplicationContext(context, servletContext);
servletContext.setAttribute(WebApplicationContext.ROOT_WEB_APPLICATION_CONTEXT_ATTRIBUTE, context);
log.debug("Done refreshing WAC");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Done refreshing WAC");

WebDaemon.startOpenmrs(event.getServletContext());
} else {
Expand Down Expand Up @@ -343,7 +343,7 @@ public static void startOpenmrs(ServletContext servletContext) throws ServletExc
// start openmrs
try {
// load bundled modules that are packaged into the webapp
log.debug("Loading bundled modules");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Loading bundled modules");
Listener.loadBundledModules(servletContext);

Context.startup(getRuntimeProperties());
Expand All @@ -358,7 +358,7 @@ public static void startOpenmrs(ServletContext servletContext) throws ServletExc
// TODO catch openmrs errors here and drop the user back out to the setup screen

try {
log.debug("Performing start of modules");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Performing start of modules");
// web load modules
Listener.performWebStartOfModules(servletContext);

Expand Down Expand Up @@ -703,7 +703,7 @@ public static void performWebStartOfModules(Collection<Module> startedModules, S

boolean someModuleNeedsARefresh = false;
for (Module mod : startedModules) {
log.debug("Staring module: {}", mod.getModuleId());
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Staring module: {}", mod.getModuleId());
try {
boolean thisModuleCausesRefresh = WebModuleUtil.startModule(mod, servletContext,
/* delayContextRefresh */true);
Expand All @@ -716,9 +716,9 @@ public static void performWebStartOfModules(Collection<Module> startedModules, S

if (someModuleNeedsARefresh) {
try {
log.debug("Refreshing WAC as required by some module");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Refreshing WAC as required by some module");
WebModuleUtil.refreshWAC(servletContext, true, null);
log.debug("Done refreshing WAC as required by some module");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Done refreshing WAC as required by some module");
}
catch (ModuleMustStartException | BeanCreationException ex) {
// pass this up to the calling method so that openmrs loading stops
Expand Down Expand Up @@ -748,9 +748,9 @@ public static void performWebStartOfModules(Collection<Module> startedModules, S
}
}
}
log.debug("Retrying refreshing WebApplicationContext");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Retrying refreshing WebApplicationContext");
WebModuleUtil.refreshWAC(servletContext, true, null);
log.debug("Done refreshing WebApplicationContext");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Done refreshing WebApplicationContext");
}
catch (MandatoryModuleException ex) {
// pass this up to the calling method so that openmrs loading stops
Expand All @@ -769,7 +769,7 @@ public static void performWebStartOfModules(Collection<Module> startedModules, S
// because we delayed the refresh, we need to load+start all servlets and filters now
// (this is to protect servlets/filters that depend on their module's spring xml config being available)
for (Module mod : ModuleFactory.getStartedModulesInOrder()) {
log.debug("Loading servlets and filters for module: {}", mod.getModuleId());
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Loading servlets and filters for module: {}", mod.getModuleId());
WebModuleUtil.loadServlets(mod, servletContext);
WebModuleUtil.loadFilters(mod, servletContext);
}
Expand Down
12 changes: 6 additions & 6 deletions web/src/main/java/org/openmrs/web/filter/initialization/InitializationFilter.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -93,7 +93,7 @@
public class InitializationFilter extends StartupFilter {

private static final org.slf4j.Logger log = LoggerFactory.getLogger(InitializationFilter.class);

private static final String DATABASE_POSTGRESQL = "postgresql";

private static final String DATABASE_MYSQL = "mysql";
Expand Down Expand Up @@ -213,7 +213,7 @@ protected synchronized void setInitializationComplete(boolean initializationComp
@Override
protected void doGet(HttpServletRequest httpRequest, HttpServletResponse httpResponse)
throws IOException {
log.debug("Entered initialization filter");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Entered initialization filter");

SessionModelUtils.loadFromSession(httpRequest.getSession(), wizardModel);
initializeWizardFromResolvedPropertiesIfPresent();
Expand Down Expand Up @@ -1345,7 +1345,7 @@ public synchronized String getMessage() {
}

public synchronized void setMessage(String message) {
log.debug(message);
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, message);
this.message = message;
setStepsComplete(getStepsComplete() + 1);
}
Expand Down Expand Up @@ -1595,7 +1595,7 @@ public void executing(ChangeSet changeSet, int numChangeSetsToRun) {
}

if (wizardModel.createTables) {
log.debug("Creating tables");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Creating tables");
// use liquibase to create core data + tables
try {
String liquibaseSchemaFileName = changeLogVersionFinder.getLatestSchemaSnapshotFilename()
Expand Down Expand Up @@ -1724,10 +1724,10 @@ public void executing(ChangeSet changeSet, int numChangeSetsToRun) {
// start spring
// after this point, all errors need to also call: contextLoader.closeWebApplicationContext(event.getServletContext())
// logic copied from org.springframework.web.context.ContextLoaderListener
log.debug("Initializing WAC");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Initializing WAC");
ContextLoader contextLoader = new ContextLoader();
contextLoader.initWebApplicationContext(filterConfig.getServletContext());
log.debug("Done initializing WAC");
log.debug(OpenmrsConstants.PERFORMANCE_MARKER, "Done initializing WAC");

// output properties to the openmrs runtime properties file so that this wizard is not run again
FileOutputStream fos = null;
Expand Down