Bad Query Logging – SQL Performance

Die Datenbankabfrage deiner Softwareanwendung dauert mal wieder viel zu lange? Eventuell handelt es sich um ein SQL Performance Problem. Nachfolgend hat sich Yavuz Yazici während seines sechs monatigen Praktikums bei avocado software engineering diesem Problem gestellt und einen smarte Lösung gefunden.

Auch mit jOOQ können schlechte Datenbankaufrufe getätigt werden, diese können zu schlechter Performanz oder gar zum Absturz einer Applikation führen. Daher ist es im Interesse jeder Backend Programmierer:in diese „bad queries“ zu vermeiden. Jedoch kann das Durchforsten des gesamten Codes auf potenziell schlechte Datenbankaufrufe sehr mühselig und ineffizient sein. Vor allem wenn es sich um komplizierte / dynamische Datenbankbefehle handelt.

Als Lösung definieren wir Metriken für schlechte Datenbankoperationen. Falls eine getätigte DB-Operation diese Metriken erfüllt, wird diese mithilfe eines Listeners geloggt. Somit muss nicht nach den Operationen gesucht werden, stattdessen werden diese einfach erkannt und geloggt. Gewissen Metadaten im Log machen es möglich die problematischen Stellen im Code schnell zu lokalisieren.

Es gibt viele Sinnvolle Metriken für schlechte Datenbankoperationen, hier eine nicht erschöpfende Liste:

  1. Zeit: Operationen die länger als X Sekunden laufen sollten evtl. kritisch betrachtet werden.
  2. Ergebnisgröße: Wenn mehr als X Ergebnisse geliefert werden, sollte man die Operation näher ansehen. Macht es evtl. sinn ein Limit einzubauen?
  3. UPDATE oder DELETE ohne where Klausel: Es gilt allgemein als sehr riskant DELETE oder UPDATA Operationen durchzuführen, ohne jegliche Begrenzung einzubauen. Schnell sind wichtige daten verlorengegangen.
  4. Select *: Es gibt nie einen Grund Select * zu verwenden. Selbst bei einfachen Aufrufen, wo alle Attribute eines Elementes gewünscht sind, sollte TABLE.values() verwendet werden. Schnell kann es passieren das bei einer großen join Operation hunderte Attribute zurückgeliefert werden, obwohl sie nicht nötig sind, im Prozess verliert man viel an Performanz.

Beachte: In diesem Blogeintrag wird nur 2. Ergebnisgröße betrachtet.

JOOQ bietet die Möglichkeit Listener einzubauen. Listerner sind Komponenten, welche bei jedem Datenbankaufruf „zuhören“. Als Beispiel könnte man einen Listener implementieren welcher bei jedem Datenbankaufruf „Hello World“ loggt.

Um einen Listener zu erstellen, muss eine Klasse erstell werden die vom DefaultExecuteListener erbt. Die Klasse bietet mehrere Methoden, die überschrieben werden können, sie dienen als Einstiegspunkte in die Datenbankoperationen. So kann man mit prepareEnd direkt nach der Erstellung des SQL-Befehles oder mit resultStart kurz vor dem Holen der Ergebnisse in die Operation eingreifen.

ResultSizeListener:

Bevor mit der Implementation eines Loggers angefangen wird, ist es ratenswert festzulegen was und wann geloggt werden soll. Es soll geloggt werden, sobald eine Datenbankoperation mehr als rowsLimit Elemente zurückgibt. In diesem Fall werden nicht nur die SQL Befehle geloggt, sondern auch der Stacktrace und diverse META-Daten über den auslösenden API-Call.

Dieser Listener besitzt mehrere Eigenschaften:

  1. Erbt von DefaultExecuteListener
  2. Besitzt Log4J Logger: ist der Logger der Wahl, kann durch andere ersetzt werden.
  3. Besitzt Int rowsLimit: ist der Maximalwert. Ist dieser überschritten soll geloggt werden.
  4. Besitzt HTTPServletRequest: um META-Daten über den API-Call loggen zu können brauchen wir die Anfrage selbst.
  5. Eigene Exception: SQLResultSizeWarning, diese Exception soll lediglich mit dem Log4J geloggt werden, somit bekommen wir unseren Stack-trace.

public class ResultSizeListener extends DefaultExecuteListener {
   
   private static final Logger logger = LoggerFactory.getLogger(ResultSizeListener.class);

   private int rowsLimit;
   private HttpServletRequest request;
 
   class SQLResultSizeWarning extends RuntimeException {}

   public ResultSizeListener(int rowsLimit, HttpServletRequest request) {
      this.rowsLimit = rowsLimit;
      this.request = request;
   }
   ...
}

Da wir das Ergebnis der Datenbankoperation betrachten wollen, überschreiben wir die end Methode. Diese Methode akzeptiert ein ExecuteCotext ctx als Parameter. ctx.rows(), gibt die Anzahl der Elemente und ctx.query().toString() gibt die SQL-Query zurück. So kann mit diesen beiden Funktionen schon bestimmt werden, ob geloggt werden soll und wenn ja, dann haben wir auch schon die SQL-Query. Für das Formatieren und Parsen der API-Call Informationen wurde eine zusätzliche Methode implementiert.

private String getRequestLog() {
   Request baseRequest = Request.getBaseRequest(this.request);
   
   return baseRequest == null ? "" : String.format(
      "Request data: {\n" + 
         "method: %s\n" +
         "path: %s\n" + 
         "uri: %s\n" +
         "content-type: %s\n" +
         "}",
      StringUtils.isNotBlank(baseRequest.getMethod()) ? baseRequest.getMethod() : "",
      StringUtils.isNotBlank(baseRequest.getServletPath()) ? baseRequest.getServletPath() : "",
      baseRequest.getMetaData() ! null && StringUtils.isNotBlank(baseRequest.getMetaData().getURIString())
         ? baseRequest.getMetaData().getURIString() : "",
      StringUtils.isNotBlank(baseRequest.getContentType()) ? baseRequest.getContentType() : "");
}

Diese Methode liefert einen JSON String mit folgenden Attributen:

  • method: was für eine HTTP-Methode war es? (GET/POST/PUT/DELETE)
  • path: welcher API Pfad wurde aufgerufen (z.B. api/v1/students/4)
  • uri: die ganze request URL
  • content-type: wenn Post, was für eine Typ von Daten wurde versendet? (JSON, sql, javascript, etc…)

Der Stacktrace ergibt sich durch das Generieren und Loggen einer SQLResultSizeWarning Exception. Alles zusammen ergibt folgenden Code:

@Override
public void end(ExecuteConext ctx) {
   if(ctx != null && ctx.rows() > rowsLimit) {
      
      String query = ctx.query() != null ? ctx.query().toString() : null;
    
      logger.warn(String.format(
         "\nToo many result fetched: size: %s, query: " + 
            "%s" +
            "\n----------------------------------------------------\n" + 
            "%s" +
            "\n----------------------------------------------------\n" +
            "%s" +
            "\n----------------------------------------------------\n",
         ctx.rows(),
         StringUtils.isNotBlank(query) ? query : "",
         this.getRquestLog()
      ), new SQLResultSizeWarning());
   }
}

Verwenden der Listener für eine bessere SQL Performance

Damit die Listener auch verwendet werden, müssen diese mithilfe von jooq.Configuration hinzugefügt werden. Zum Erstellen einer Konfiguration verwenden wir den new DefaultConfition() Konstruktor.

org.jooq.Configuration configuration = new DefaultConfiguration();

Dieser Konfigurations-Klasse bietet eine derive(ExecuteListernerProvier… args) Methode. Durch diese übergeben wir unsere Listener. Zuletzt muss diese Konfiguration noch als @Bean zur Verfügung gestellt werden.

@Bean
public org.jooq.Configuration jooqConfiguration(ConnectionProvider connectionProvider,
                                                HttpServletRequest request) {
   org.jooq.Configuration configuration = new DefaultConfiguration()
       .derive(connectionProvider)
       .derive(SQLDialect.MYSQL)
       .derive(new DefaultExecuteListenerProvider(
           new ResultSizeListener(1000, request)));
   
   return configuration;
}

In diesem Fall wurde ein ResultSizeListener mit rowsLimit 1000 hinzugefügt. Dieser Wert sollte nun frei wählbar gemacht werden, zudem sollte es möglich sein über die application.properties den Listener an und aus zu stellen. Um dies zu gewährleisten erstellen wir eine JooqSettings-Klasse. Diese Klasse nutzt Spring Boots @ConfigurationProperties um Werte aus der application.properties Datei in Java zu laden. Diese Klasse besitzt zwei Attribute:

  1. Integer rowsLimit
  2. boolean listenerEnabled
@Component
@ConfigurationProperties(prefix="jooq.logger")
public class JooqSettings {
   
   private Integer rowsLimit;

   private boolean listenerEnabled;

   public Integer getResultSizeListenerRowsLimit() {return rowsLimit;}

   public void setResultSizeListenerRowsLimit(Integer rowsLimit) {this.rowsLimit = rowsLimit;}

   public boolean isListenerEnabled() {return listenerEnabled;}

   public void setListenerEnabled(boolean listenerEnabled) {this.listenerEnabled = listenerEnabled;}
}

Beachte: Damit rowsLimit und listenerEnabled gesetzt sind, müssen diese Werte in application.properties vorhanden sein.

jooq.logger.rows-limit=1000
jooq.logger.listener-enabled=true

Die Verantwortung zu bestimmen, ob und welcher Listener mit welchen Parameter hinzugefügt werden soll, wurde in eine separate Methode ausgelagert.

Somit sieht die jooqConfiguration Methode nun wie folgt aus:

private DefaultExecuteListenerProvider[] getExecuteListenerProviders(JooqSettings jooqSettings, 
                                                                     HttpServletRequest request) {
   List<DefaultExecuteListenerProvider> executeListenerProviderList = new ArrayList<>();
 
   if(jooqSettings.isResultSizeListenerEnable()) {
      executeListenerProviderList.add(new DefaultExecuteListenerProvider(
         new ResultSizeListener(jooqSettings.getResultSizeListenerRowsLimit(), request)));
   }
 
   return executeListenerProviderList
      .toArray(new DefaultExecuteListenerProvider[executeListenerProviderList.size()]);
}

Somit ist jOOQ jetzt konfiguriert und die hinzugefügten Listener werden verwendet. Ein Beispiellog des ResultSizeListeners sieht wie folgt aus:

21:25:58:653 [qtp1396626286-110] WARN  de.avocado.dap.settings.sql.ResultSizeListener - 
Too many result fetched: size: 5, query: 
-----------------------------------------------
select 'database_name'.'table_name'.'column_name'
from 'database_name'.'table_name'
where 'database_name'.'table_name'.'column_name' = 53
-----------------------------------------------
Request data: {
method: GET
path: /api/company/53
uri: //localhost:8082/api/company/53
content-type: application/json
}
-----------------------------------------------
de.avocado.dap.settings.sql.ResultSizeListener$SQLResultSizeWarning: null
        at de.avocado.dap.settings.sql.ResultSizeListener.end(ResultSizeListener.java:38) ~[classes/:?]
        at org.jooq.impl.ExecuteListeners.end(ExecuteListeners.java:263) ~[jooq-3.15.1.jar:?]
        at org.jooq.impl.Tools.safeClose(Tools.java:3042) ~[jooq-3.15.1.jar:?]
        at org.jooq.impl.CursorImpl$CursorResultSet.close(CursorImpl.java:421) ~[jooq-3.15.1.jar:?]
        at org.jooq.tools.jdbc.JDBCUtils.safeClose(JDBCUtils.java:656) ~[jooq-3.15.1.jar:?]
        at org.jooq.impl.CursorImpl.close(CursorImpls.java:231) ~[jooq-3.15.1.jar:?]

  *Für Beispielzwecke wurde rowsLimit auf 4 gesetzt

Bei avocado software engineering wurde mir immer die Möglichkeit gegeben mich in ein Thema zu vertiefen. So fand ich bessere und optimalere Lösungen als es in Standardpraktiken üblich ist.

Yavuz Yazici (Student Angewandte Informatik, 5. Semester)

Veröffentlicht am 23. Februar 2022