Nous avons eu, il a quelque temps des problèmes de performance en production. Notre stack technologique est composée de Tomcat, Spring, Hibernate, JSF … autant de Framework qui automatisent énormément de choses, génèrent du code …
Que faire quand un service qui met 100 ms en DEV passe à 30 secondes en PROD ?
Notre premier réflexe, activer le niveau DEBUG des logs en production. Il FAUT que l’on ait plus de visibilité sur ce qu’il se passe !
… Heu ! Changer le niveau de logs en production implique “changer la configuration et redémarrer Tomcat” ?! Évidement, nous avons des scrupules à le faire .
Alors, comment changer son niveau de logs à chaud ?
Certaines API de logs vous proposent un MBean JMX pour le faire. Nous avons eu la chance de choisir comme API de log SLF4J et Logback comme implémentation. Logback permet activer son MBean via une ligne de configuration. Dans le logback.xml
<configuration> … <jmxConfigurator /> </configuration>
En utilisant JConsole, vous pouvez avoir accès au MBean Logback comme suit.
En utilisant la méthode setLoggerLevel(“MonLogger”, DEBUG) on peut passer le niveau de logs à DEBUG à chaud.
Certains Loggers, tel que ceux de Spring notamment peuvent ne pas changer de niveau de logs lors de cet appel. Ces frameworks n’utilisent pas SLF4J comme API de logs. Pour que cette fonctionnalité soit applicable à tous vos loggers, il vous faut rationaliser vos logs. Tous vos loggers devraient passer par SLF4J. Cela est possible en utilsant des bridges SLF4J (http://www.slf4j.org/legacy.html) .
Une fois que tous vos loggers passeront par logback, vous êtes sûr de pouvoir tous les impacter à chaud.
Nous avons donc ainsi pu découvrir que nous avions un problème de mapping Hibernate qui nous générait N+1 requètes SQL sur une table qui était presque vide en DEV. Nous avons pu revoir le mapping et le code de sorte à retomber sur les performances attendues.
Aujourd’hui …
Nous avons beaucoup plus de clients, et beaucoup plus de trafic. Nous avons encore des problèmes de performance sur certains processus métier. Il nous a été remonté qu’un processus qui dit prendre 2 minutes dans les logs, prenait en fait à certains moments 5 heures. 5 heures pendant lesquels nous sommes dans le noir complet. Ce cas ne se reproduit quand production. Nous avons donc encore une fois besoin d’allumer les lumières, activer le niveau DEBUG des logs.
Mais là, … les OPS nous disent NON!
“Activer les logs hibernate, avec tout ce trafic, nous générerait beaucoup trop de logs!”. Il faudrait pouvoir activer ces logs que sur un client particulier.
Comment activer à chaud le niveau DEBUG sur UN client ?
D’abord, nous devons pouvoir reconnaître une ligne de logs comme étant celle d’un client. Pour cela, nous aurons recours au Mapped Diagnostic Context (MDC). Vous l’avez peut être déjà utilisé pour y enregistrer le fameux jsessionid sur les applications web. Nous allons donc y enregistrer le clientId .
Nous devons, à présent, nous baser sur ce clientId pour filtrer nos logs.
Un certain nombre de recherche sur google ne nous donne rien.
Regardons dans la doc de Logback … Un chapitre sur les Filtres … Les TurboFilters !
Ok! Nous devons donc implémenter notre TurboFilter. Il doit filtrer en se basant sur le MDC et sur le Niveau de LOG qui lui est communiqué pour un certain logger.
package fr.wattazoum.help;
import java.util.Collection;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.slf4j.Marker;
import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.turbo.TurboFilter;
import ch.qos.logback.core.spi.FilterReply;
import com.google.common.collect.HashMultimap;
import com.google.common.collect.Multimap;
public class ClientTurboFilter extends TurboFilter {
private static class LoggerNameLevelTuple {
private String loggerName;
private String loggerNameRegexp;
private Level level;
private LoggerNameLevelTuple(String loggerName, Level level) {
String loggerNameRegexp = loggerName.replaceAll("\\.", "\\.");
loggerNameRegexp += "(\\..*)?";
this.loggerName = loggerName;
this.loggerNameRegexp = loggerNameRegexp;
this.level = level;
}
@Override
public String toString() {
return "{" + loggerName + "=>" + level + "}";
}
}
private static final Multimap clientIdToLogLevelMap = HashMultimap.create();
@Override
public FilterReply decide(Marker marker, Logger logger, Level level, String format, Object[] params, Throwable t) {
String clientId = MDC.get("clientId");
if (clientIdToLogLevelMap.containsKey(clientId)) {
Collection tupleList = clientIdToLogLevelMap.get(clientId);
for (LoggerNameLevelTuple loggerNameLevelTuple : tupleList) {
if (logger.getName().matches(loggerNameLevelTuple.loggerNameRegexp)) {
if (level.isGreaterOrEqual(loggerNameLevelTuple.level)) {
return FilterReply.ACCEPT;
} else {
return FilterReply.DENY;
}
}
}
}
return FilterReply.NEUTRAL;
}
public synchronized static void addClientIdLogLevel(String clientId, String loggerName, String levelStr) {
Level level = Level.toLevel(levelStr);
clientIdToLogLevelMap.put(clientId, new LoggerNameLevelTuple(loggerName, level));
}
public static String getLoggerLevel(String clientId, String loggerName) {
Logger logger = (Logger) LoggerFactory.getLogger(loggerName);
Level level = logger.getEffectiveLevel();
if (clientIdToLogLevelMap.containsKey(clientId)) {
Collection tupleList = clientIdToLogLevelMap.get(clientId);
for (LoggerNameLevelTuple loggerNameLevelTuple : tupleList) {
if (loggerName.matches(loggerNameLevelTuple.loggerNameRegexp)) {
return loggerNameLevelTuple.level.toString();
}
}
}
return level.toString();
}
public synchronized static void removeClientId(String clientId) {
clientIdToLogLevelMap.removeAll(clientId);
}
public synchronized static void clear() {
clientIdToLogLevelMap.clear();
}
public static String getLoggersSettings() {
return clientIdToLogLevelMap.toString();
}
}
Il nous faut maintenant configurer Logback afin de prendre en compte notre TurboFilter. Dans le logback.xml
<configuration> … <turboFilter class="fr.wattazoum.help.ClientTurboFilter"/> <jmxConfigurator /> </configuration>
Et le MBean correspondant
package fr.wattazoum.help;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.jmx.export.annotation.ManagedAttribute;
import org.springframework.jmx.export.annotation.ManagedOperation;
import org.springframework.jmx.export.annotation.ManagedOperationParameter;
import org.springframework.jmx.export.annotation.ManagedOperationParameters;
import org.springframework.jmx.export.annotation.ManagedResource;
import org.springframework.stereotype.Component;
@Component
@ManagedResource
public class LogManagementMBean {
private static final Logger LOGGER = LoggerFactory.getLogger(LogManagementMBean.class);
@ManagedAttribute
public String getLoggersStatus() {
return ClientTurboFilter.getLoggersSettings();
}
@ManagedOperation
@ManagedOperationParameters({
@ManagedOperationParameter(name = "clientId", description = "The clientId to act on."),
@ManagedOperationParameter(name = "loggerName", description = "The logger to act on.")})
public String getLoggerLevel(String clientId, String loggerName) {
return ClientTurboFilter.getLoggerLevel(clientId, loggerName);
}
@ManagedOperation
@ManagedOperationParameters({
@ManagedOperationParameter(name = "clientId", description = "The clientId to act on."),
@ManagedOperationParameter(name = "loggerName", description = "The logger to act on."),
@ManagedOperationParameter(name = "level", description = "The level to set.")})
public void setLoggerLevel(String clientId, String loggerName, String level) {
ClientTurboFilter.addClientIdLogLevel(clientId, loggerName, level);
}
@ManagedOperation
@ManagedOperationParameters({
@ManagedOperationParameter(name = "clientId", description = "The clientId to act on.")})
public void removeSettingsForGroupeId(String clientId) {
ClientTurboFilter.removeClientId(clientId);
}
@ManagedOperation(description="remove every settings on every clientId")
public void reset() {
LOGGER.debug("Removing settings on everyClientIds");
ClientTurboFilter.clear();
}
}
Nous utilisons Spring pour l’enregistrement des MBean et leur description. Avec ce MBean, je peux changer à chaud, pour un client, le niveau de log d’un logger.
Et nos problèmes de perf dans tout ça? Après avoir activé les logs hibernate, nous avons vu que ce qui prenait du temps, c’était le COMMIT de la transaction SQL. Mais ceci est dû à une configuration du serveur de base de données qui supporte mal les très grosses transactions.
L’importance des logs en prod, n’est plus à démontrer, ce qui pourrait ensuite apparaitre comme une lumière quand tout est obscure, ce sont les logs invisibles en temps normal. Avoir un moyen de les allumer devient alors un plus non négligeable pour vos OPS et pour vous. La première chose que je voulais ainsi partager avec vous, c’est:
Donnons nous les moyens d’allumer nos logs en prod!
