Voorwaardelijke logging met minimale cyclomatische complexiteit

Na het lezen van “Wat is uw/een goede limiet voor cyclomatische complexiteit?“, realiseer ik me dat veel van mijn collega’s behoorlijk geïrriteerd waren door deze nieuwe QA-beleid voor ons project: niet meer 10 cyclomatische complexiteitper functie.

Betekenis: niet meer dan 10 ‘if’, ‘else’, ‘try’, ‘catch’ en andere code-workflow-vertakkingsinstructies. Rechts. Zoals ik heb uitgelegd in ‘Test u de privémethode?‘, is een dergelijk beleid heeft veel goede bijwerkingen.

Maar: aan het begin van ons (200 mensen – 7 jaar lang) project waren we met plezier aan het loggen (en nee, dat kunnen we niet gemakkelijk delegeren aan een soort ‘Aspect-georiënteerd programmeren‘ benadering voor logbestanden).

myLogger.info("A String");
myLogger.fine("A more complicated String");
...

En toen de eerste versies van ons systeem live gingen, ondervonden we een enorm geheugenprobleem, niet vanwege de logging (die op een gegeven moment was uitgeschakeld), maar vanwege de logparameters(de strings ), die altijd worden berekend en vervolgens worden doorgegeven aan de functies ‘info()’ of ‘fine()’, om te ontdekken dat het niveau van logboekregistratie ‘UIT’ was en dat er geen logboekregistratie plaatsvond!

Dus QA kwam terug en drong er bij onze programmeurs op aan om voorwaardelijke logging te doen. Altijd.

if(myLogger.isLoggable(Level.INFO) { myLogger.info("A String");
if(myLogger.isLoggable(Level.FINE) { myLogger.fine("A more complicated String");
...

Maar nu, met dat ‘niet-verplaatsbare’ 10 cyclomatische complexiteitsniveau per functielimiet, beweren ze dat de verschillende logs die ze in hun functie plaatsen als een last worden ervaren, omdat elke “if(isLoggable() )” wordt geteld als +1 cyclomatische complexiteit!

Dus als een functie 8 ‘if’, ‘else’ enzovoort heeft, in één nauw gekoppeld, niet gemakkelijk te delen algoritme, en 3 kritieke logacties… overschrijden ze de limiet, ook al kunnen de voorwaardelijke logs geen echtdeel uitmaken van de complexiteit van die functie…

Hoe zou u deze situatie aanpakken?
Ik heb een aantal interessante coderingsevoluties gezien (vanwege dat ‘conflict’) in mijn project, maar ik wil eerst jullie gedachten krijgen.

Bedankt voor alle antwoorden.
Ik moet erop hameren dat het probleem niet ‘opmaak’-gerelateerd is, maar ‘argumentevaluatie’-gerelateerd (evaluatie die erg duur kan zijn om te doen, net voordat een methode wordt aangeroepen die niets zal doen)
Dus toen a hierboven “A String” schreef, bedoelde ik eigenlijk aFunction(), waarbij aFunction() een String retourneert, en een oproep is naar een gecompliceerde methode die alle soorten loggegevens verzamelt en berekent die door de logger moeten worden weergegeven… of niet (vandaar het probleem, en de verplichtingom voorwaardelijke logging te gebruiken, vandaar het feitelijke probleem van kunstmatige toename van ‘cyclomatische complexiteit’…)

Ik krijg nu de ‘variadic-functie’-punt voorgeschoten door sommigen van jullie (dank je John ).
Opmerking: een snelle test in java6 laat zien dat mijn varargs-functieevalueert zijn argumenten voordat ze worden aangeroepen, dus het kan niet worden toegepast voor functieaanroep, maar voor ‘Log retriever-object’ (of ‘function wrapper’), waarop de toString() alleen wordt aangeroepen als dat nodig is. Begrepen.

Ik heb nu mijn ervaring over dit onderwerp gepost.
Ik laat het daar liggen tot volgende week dinsdag om te stemmen, dan zal ik een van je antwoorden selecteren.
Nogmaals bedankt voor alle suggesties 🙂

Antwoord 1, autoriteit 100%

Met de huidige logging-frameworks is de vraag onbetwist

Huidige logging-frameworks zoals slf4j of log4j 2 vereisen in de meeste gevallen geen guard-statements. Ze gebruiken een logboekinstructie met parameters zodat een gebeurtenis onvoorwaardelijk kan worden vastgelegd, maar berichtopmaak vindt alleen plaats als de gebeurtenis is ingeschakeld. Berichtconstructie wordt naar behoefte uitgevoerd door de logger, in plaats van preventief door de applicatie.

Als je een antieke logboekbibliotheek moet gebruiken, kun je verder lezen voor meer achtergrondinformatie en een manier om de oude bibliotheek uit te rusten met geparameteriseerde berichten.

Verhogen bewakingsverklaringen echt complexiteit?

Overweeg om logging guard-statements uit te sluiten van de cyclomatic complexiteitsberekening.

Je zou kunnen stellen dat, vanwege hun voorspelbare vorm, voorwaardelijke logboekcontroles echt niet bijdragen aan de complexiteit van de code.

Inflexibele statistieken kunnen ervoor zorgen dat een anders goede programmeur slecht wordt. Wees voorzichtig!

Ervan uitgaande dat uw tools voor het berekenen van complexiteit niet in die mate kunnen worden aangepast, kan de volgende aanpak een tijdelijke oplossing bieden.

De noodzaak van voorwaardelijke logging

Ik neem aan dat uw waarschuwingsverklaringen zijn geïntroduceerd omdat u een code als deze had:

private static final Logger log = Logger.getLogger(MyClass.class);
Connection connect(Widget w, Dongle d, Dongle alt) 
  throws ConnectionException
{
  log.debug("Attempting connection of dongle " + d + " to widget " + w);
  Connection c;
  try {
    c = w.connect(d);
  } catch(ConnectionException ex) {
    log.warn("Connection failed; attempting alternate dongle " + d, ex);
    c = w.connect(alt);
  }
  log.debug("Connection succeeded: " + c);
  return c;
}

In Java maakt elk van de log-instructies een nieuwe StringBuilderaan en roept de methode toString()aan op elk object dat aan de tekenreeks is gekoppeld. Deze toString()-methoden zullen op hun beurt waarschijnlijk hun eigen StringBuilder-instanties maken en de toString()-methoden van hun leden aanroepen , enzovoort, over een potentieel grote objectgrafiek. (Vóór Java 5 was het zelfs nog duurder, omdat StringBufferwerd gebruikt en alle bewerkingen worden gesynchroniseerd.)

Dit kan relatief duur zijn, vooral als de log-instructie zich in een zwaar uitgevoerd codepad bevindt. En, zoals hierboven geschreven, die dure berichtopmaak gebeurt zelfs als de logger het resultaat moet weggooien omdat het logniveau te hoog is.

Dit leidt tot de introductie van bewakingsverklaringen van de vorm:

 if (log.isDebugEnabled())
    log.debug("Attempting connection of dongle " + d + " to widget " + w);

Met deze bewaker wordt de evaluatie van de argumenten den wen de tekenreeksaaneenschakeling alleen uitgevoerd als dat nodig is.

Een oplossing voor eenvoudige, efficiënte logging

Als de logger (of een wrapper die u om het door u gekozen logpakket schrijft) echter een formatter en argumenten voor de formatter gebruikt, kan de berichtconstructie worden uitgesteld totdat het zeker is dat deze zal worden gebruikt, terwijl de beveiliging wordt geëlimineerd uitspraken en hun cyclomatische complexiteit.

public final class FormatLogger
{
  private final Logger log;
  public FormatLogger(Logger log)
  {
    this.log = log;
  }
  public void debug(String formatter, Object... args)
  {
    log(Level.DEBUG, formatter, args);
  }
  … &c. for info, warn; also add overloads to log an exception …
  public void log(Level level, String formatter, Object... args)
  {
    if (log.isEnabled(level)) {
      /* 
       * Only now is the message constructed, and each "arg"
       * evaluated by having its toString() method invoked.
       */
      log.log(level, String.format(formatter, args));
    }
  }
}
class MyClass 
{
  private static final FormatLogger log = 
     new FormatLogger(Logger.getLogger(MyClass.class));
  Connection connect(Widget w, Dongle d, Dongle alt) 
    throws ConnectionException
  {
    log.debug("Attempting connection of dongle %s to widget %s.", d, w);
    Connection c;
    try {
      c = w.connect(d);
    } catch(ConnectionException ex) {
      log.warn("Connection failed; attempting alternate dongle %s.", d);
      c = w.connect(alt);
    }
    log.debug("Connection succeeded: %s", c);
    return c;
  }
}

Nu, geen van de trapsgewijze toString()-aanroepen met hun buffertoewijzingen zal plaatsvindentenzij ze nodig zijn! Dit elimineert effectief de prestatiehit die leidde tot de bewakingsverklaringen. Een kleine straf, in Java, zou het automatisch inpakken van primitieve typeargumenten zijn die u aan de logger doorgeeft.

De code die de logging doet, is aantoonbaar zelfs schoner dan ooit, aangezien de slordige aaneenschakeling van strings is verdwenen. Het kan zelfs schoner zijn als de formaatstrings worden geëxternaliseerd (met behulp van een ResourceBundle), wat ook kan helpen bij het onderhoud of de lokalisatie van de software.

Verdere verbeteringen

Houd er ook rekening mee dat in Java een object MessageFormatkan worden gebruikt in plaats van een “format” String, wat u extra mogelijkheden geeft, zoals een keuzeformaat om ga netter om met hoofdtelwoorden. Een ander alternatief zou zijn om uw eigen formatteringsmogelijkheid te implementeren die een interface aanroept die u definieert voor “evaluatie”, in plaats van de basismethode toString().

Antwoord 2, autoriteit 52%

In Python geef je de opgemaakte waarden als parameters door aan de logging-functie. Tekenreeksopmaak wordt alleen toegepast als logboekregistratie is ingeschakeld. Er is nog steeds de overhead van een functieaanroep, maar dat is minuscuul vergeleken met opmaak.

log.info ("a = %s, b = %s", a, b)

Je kunt zoiets doen voor elke taal met variadische argumenten (C/C++, C#/Java, enz.).

Dit is niet echt bedoeld voor wanneer de argumenten moeilijk te achterhalen zijn, maar voor wanneer het formatteren ervan naar strings duur is. Als uw code bijvoorbeeld al een lijst met nummers bevat, wilt u misschien die lijst vastleggen voor foutopsporing. Het uitvoeren van mylist.toString()zal enige tijd duren zonder voordeel, omdat het resultaat wordt weggegooid. Dus je geeft mylistdoor als parameter aan de logfunctie, en laat het de tekenreeksopmaak afhandelen. Op die manier wordt formatteren alleen uitgevoerd als dat nodig is.

Aangezien de OP-vraag specifiek Java vermeldt, kunt u het bovenstaande als volgt gebruiken:

Ik moet volhouden dat het probleem niet ‘opmaak’-gerelateerd is, maar ‘argumentevaluatie’-gerelateerd (evaluatie die erg duur kan zijn om te doen, net voordat een methode wordt aangeroepen die niets zal doen)

De truc is om objecten te hebben die geen dure berekeningen zullen uitvoeren totdat ze absoluut nodig zijn. Dit is gemakkelijk in talen als Smalltalk of Python die lambda’s en sluitingen ondersteunen, maar is met een beetje fantasie nog steeds te doen in Java.

Stel dat je een functie get_everything()hebt. Het haalt elk object uit uw database op in een lijst. Je wilt dit natuurlijk niet noemen als het resultaat wordt weggegooid. Dus in plaats van rechtstreeks een aanroep van die functie te gebruiken, definieert u een innerlijke klasse met de naam LazyGetEverything:

public class MainClass {
    private class LazyGetEverything { 
        @Override
        public String toString() { 
            return getEverything().toString(); 
        }
    }
    private Object getEverything() {
        /* returns what you want to .toString() in the inner class */
    }
    public void logEverything() {
        log.info(new LazyGetEverything());
    }
}

In deze code is de aanroep van getEverything()verpakt, zodat deze niet daadwerkelijk wordt uitgevoerd totdat deze nodig is. De logfunctie zal toString()alleen op zijn parameters uitvoeren als foutopsporing is ingeschakeld. Op die manier heeft je code alleen last van de overhead van een functieaanroep in plaats van de volledige getEverything()-aanroep.

Antwoord 3, autoriteit 9%

In talen die lambda-expressies of codeblokken als parameters ondersteunen, zou een oplossing hiervoor zijn om precies dat aan de logmethode te geven. Dat men de configuratie zou kunnen evalueren en alleen indien nodig het verstrekte lambda/code-blok zou kunnen aanroepen/uitvoeren.
Heb het echter nog niet geprobeerd.

theoretisch Dit is mogelijk. Ik zou het niet leuk vinden om het in productie te gebruiken vanwege prestatieproblemen die ik verwacht met dat zware gebruik van Lamdas / Codeblokken voor loggen.

Maar zoals altijd: test in twijfel het en meet de impact op CPU-belasting en geheugen.

Antwoord 4, Autoriteit 6%

Bedankt voor al uw antwoorden! Jullie rocken 🙂

Nu is mijn feedback niet zo eenvoudig als de jouwe:

Ja, voor één project (zoals in ‘Eén programma geïmplementeerd en uitgevoerd op een eigen productieplatform’), veronderstel ik dat u alle technische op mij kunt gaan:

• Dedicated ‘Log Retriever’ -objecten, die kunnen worden doorgegeven aan een logger wrapper alleen bellen naar tostring () is noodzakelijk
• gebruikt in combinatie met een logging Variadic functie (of een gewone object [] array! )

En daar heb je het, zoals uitgelegd door @John Millikin en @erickson.

Dit probleem dwong ons echter om een ​​beetje over te denken ‘waarom waren we precies inloggen in de eerste plaats?’
Ons project is eigenlijk 30 verschillende projecten (elk van 5 tot 10 personen) ingezet op verschillende productieplatforms, met asynchrone communicatiebehoeften en centrale busarchitectuur.
De eenvoudige logging beschreven in de vraag was prima voor elk project aan het begin (5 jaar geleden), maar sindsdien moeten we opstaan. Voer de kpi .

In plaats van te vragen naar een logger om iets te loggen, vragen we naar een automatisch gemaakt object (KPI) om een ​​evenement te registreren. Het is een eenvoudige oproep (mykpi.i_am_signaling_myself_to_you ()), en hoeft niet voorwaardelijke (die de ‘kunstmatige toename van de cyclaomatische complexiteit’ van complexiteit) oplost).

Dat KPI-object weet wie het noemt en omdat hij vanaf het begin van de applicatie loopt, kan hij veel gegevens ophalen die we eerder ter plaatse waren toen we loggen.
Bovendien kan KPI-object onafhankelijk worden gecontroleerd en de informatie op aanvraag op een enkele en afzonderlijke publicatiebus moeten worden gecontroleerd / publiceren.
Op die manier kan elke klant om de informatie vragen die hij eigenlijk wil (zoals ‘, is mijn proces begonnen, en zo ja, sinds wanneer?’), In plaats van op zoek naar het juiste logbestand en greppen voor een cryptische string …

Inderdaad, de vraag ‘Waarom waren we precies inloggen in de eerste plaats?’ Made ons beseffen dat we niet alleen inloggen voor de programmeur en zijn eenheid of integratietests, maar voor een veel bredere gemeenschap inclusief enkele van de eindklanten zelf. Ons mechanisme ‘Rapportage’ moest gecentraliseerd, asynchroon, 24/7.

Het specifieke van dat KPI-mechanisme is ver uit de reikwijdte van deze vraag. Het volstaat om te zeggen dat de juiste kalibratie veruit, handt, de meest gecompliceerde niet-functionele kwestie waarmee we worden geconfronteerd. Het brengt het systeem nog steeds van tijd tot tijd op zijn knie! Goed gekalibreerd, het is echter een levenspaarder.

Nogmaals, bedankt voor alle suggesties. We zullen ze beschouwen voor sommige delen van ons systeem wanneer eenvoudige logging nog steeds op zijn plaats is.
Maar het andere punt van deze vraag was om een ​​specifiek probleem in een veel grotere en meer gecompliceerde context te illustreren.
Ik hoop dat je het leuk vind. Ik kan een vraag stellen over KPI (die, geloven of niet, niet in geen enkele vraag is op SOF!) Later volgende week.

Ik zal dit antwoord verlaten om tot de volgende dinsdag te stemmen, dan zal ik een antwoord selecteren (niet deze vanzelfsprekend))

Antwoord 5, Autoriteit 6%

Misschien is dit te eenvoudig, maar hoe zit het met het gebruik van de “Extract-methode” Refactoring rond de bewakingsclausule? Uw voorbeeldcode hiervan:

public void Example()
{
  if(myLogger.isLoggable(Level.INFO))
      myLogger.info("A String");
  if(myLogger.isLoggable(Level.FINE))
      myLogger.fine("A more complicated String");
  // +1 for each test and log message
}

wordt dit:

public void Example()
{
   _LogInfo();
   _LogFine();
   // +0 for each test and log message
}
private void _LogInfo()
{
   if(!myLogger.isLoggable(Level.INFO))
      return;
   // Do your complex argument calculations/evaluations only when needed.
}
private void _LogFine(){ /* Ditto ... */ }

Antwoord 6, autoriteit 5%

In C of C++ zou ik de preprocessor gebruiken in plaats van de if-statements voor de voorwaardelijke logging.

Antwoord 7, autoriteit 5%

Geef het logniveau door aan de logger en laat hem beslissen of hij de logverklaring wel of niet schrijft:

//if(myLogger.isLoggable(Level.INFO) {myLogger.info("A String");
myLogger.info(Level.INFO,"A String");

UPDATE: Ah, ik zie dat je de log-string voorwaardelijk wilt maken zonder een voorwaardelijke instructie. Vermoedelijk tijdens runtime in plaats van compileertijd.

Ik zeg alleen dat we dit hebben opgelost door de opmaakcode in de loggerklasse te plaatsen, zodat de opmaak alleen plaatsvindt als het niveau wordt gehaald. Zeer vergelijkbaar met een ingebouwde sprintf. Bijvoorbeeld:

myLogger.info(Level.INFO,"A String %d",some_number);   

Dat zou aan uw criteria moeten voldoen.

Antwoord 8, autoriteit 3%

Voorwaardelijk loggen is slecht. Het voegt onnodige rommel toe aan uw code.

Je moet altijd de objecten die je hebt naar de logger sturen:

Logger logger = ...
logger.log(Level.DEBUG,"The foo is {0} and the bar is {1}",new Object[]{foo, bar});

en dan een java.util.logging.Formatter hebben die MessageFormat gebruikt om foo en bar af te vlakken in de tekenreeks die moet worden uitgevoerd. Het wordt alleen aangeroepen als de logger en handler op dat niveau loggen.

Voor extra plezier zou je een soort expressietaal kunnen hebben om fijne controle te krijgen over hoe de gelogde objecten moeten worden opgemaakt (toString is misschien niet altijd handig).

Antwoord 9, autoriteit 3%

_{(bron: scala-lang.org)}

Scalaheeft een annotatie @elidable()waarmee je methoden met een compilervlag kunt verwijderen.

Met de scala REPL:

C:>scala

Welkom bij Scala versie 2.8.0.final (Java HotSpot(TM) 64-bits server-VM, Java 1.
6.0_16).
Typ uitdrukkingen om ze te laten evalueren.
Typ :help voor meer informatie.

scala> import scala.annotation.elidable
import scala.annotation.elidable

scala> import scala.annotation.elidable._
import scala.annotation.elidable._

scala> @elidable(FINE) def logDebug(arg :String) = println(arg)

logDebug: (arg: String)Eenheid

scala> logDebug(“testen”)

scala>

Met elide-beloset

C:>scala -Xelide-below 0

Welkom bij Scala versie 2.8.0.final (Java HotSpot(TM) 64-bits server-VM, Java 1.
6.0_16).
Typ uitdrukkingen om ze te laten evalueren.
Typ :help voor meer informatie.

scala> import scala.annotation.elidable
import scala.annotation.elidable

scala> import scala.annotation.elidable._
import scala.annotation.elidable._

scala> @elidable(FINE) def logDebug(arg :String) = println(arg)

logDebug: (arg: String)Eenheid

scala> logDebug(“testen”)

testen

scala>

Zie ook Definitie van Scala-bewering

Antwoord 10, autoriteit 2%

Hoezeer ik macro’s in C/C++ ook haat, op het werk hebben we #defines voor het if-gedeelte, dat als false de volgende expressies negeert (niet evalueert), maar als true een stream retourneert waarin dingen kunnen worden gepipetteerd met behulp van de ‘<<‘ exploitant.
Zoals dit:

LOGGER(LEVEL_INFO) << "A String";

Ik neem aan dat dit de extra ‘complexiteit’ die uw tool ziet, zou elimineren, en ook het berekenen van de tekenreeks, of alle uitdrukkingen die moeten worden vastgelegd als het niveau niet werd bereikt, elimineert.

Antwoord 11, autoriteit 2%

Hier is een elegante oplossing met ternaire uitdrukking

logger.info(logger.isInfoEnabled() ? “Loginstructie komt hier…” : null);

Antwoord 12, autoriteit 2%

Overweeg een logging util-functie …

void debugUtil(String s, Object… args) {
   if (LOG.isDebugEnabled())
       LOG.debug(s, args);
   }
);

Maak dan de oproep met een “afsluiting” rond de dure evaluatie die u wilt vermijden.

debugUtil(“We got a %s”, new Object() {
       @Override String toString() { 
       // only evaluated if the debug statement is executed
           return expensiveCallToGetSomeValue().toString;
       }
    }
);