常见的记录错误

哈Ha!


我认为几乎每个程序都有日志记录。 而且,在许多新的应用程序中(这意味着大量的非平凡条件),日志通常在战斗服务器上变得至关重要。


但是,尽管这种技术非常重要和盛行,但我注意到人们在使用它们时经常会犯标准错误。 本文从多个方面描述了.Net的行为,但是,我还是从Java世界中插入了一些小插件,只是为了进行比较。


分配(内存分配)


最常见的错误(根据我的观察)是与调用log.Debug(...)函数的位置附近的小内存分配有关的疏忽。


因此,我们在.Net中的标准代码:


 private static readonly ILog Log4NetLog = LogManager.GetLogger(typeof(Program)); private static readonly Logger NLogLog = NLog.LogManager.GetCurrentClassLogger(); private static void PublishData(int id, string name, EMail email, decimal amount) { Log4NetLog.Debug($"Id={id}"); // 1 Log4NetLog.DebugFormat("Id={0}", id); // 2 Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3 Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4 NLogLog.Debug($"Id={id}"); // 5 NLogLog.Debug("Id={0}", id); // 6 NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 7 NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 8 } 

在许多方面,我仅看到了log4netNLog库,因此在示例中将使用它们。


所以问题是:


  • 即使关闭Debug,在哪些行中也会分配内存?
  • 如果分配了内存,那么在同一个dotTrace中检测到记录器为此特别分配内存的责任有多容易呢?

对第一个问题的正确答案:不仅在“ 6”段中分配了内存。 第二个问题的答案是:很难捕获,因为这样的代码通常散布在整个项目中。 您可能会想起典型的.Net应用程序。 它通常会具有使GC工作的类似代码。


但是,让我们仔细阅读技术细节,以准确了解会对性能产生影响的地方。


因此,第一点是:


 Log4NetLog.Debug($"Id={id}"); // 1 

实际上,编译器会将其转换为:


 var temp = string.Format("Id={0}", id); // <--       Log4NetLog.Debug(temp); 

也就是说,第一个表达式实际上将迫使处理器创建一个字符串,并将其传递给记录器。 他将快速检查您是否不需要登录,因此该行仅在内存中创建。 而且,重要的是,如果您复制更多这样的代码,那么将在程序位置的堆中创建这些行,也就是说,程序的运行速度会稍微慢一些。 无处不在。


第二个示例效率更高,因为未在其中创建行:


 Log4NetLog.DebugFormat("Id={0}", id); 

但是,此处仍会分配内存,因为将发生装箱。 让我提醒您DebugFormat方法的签名:


 void DebugFormat(string format, object arg0) 

如您所见,输入需要引用类型。 但是,我们正在尝试传递有意义的int类型。 结果,每次调用都会导致传递堆参数id并将其传递给方法。 并且让我提醒您,由于任务的条件关闭了Debug ,因此方法本身不需要参数本身。


以下示例已加载并且很简单:


 Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3 

我确信您已经了解到,该行将再次在堆上突出,依此类推。 因此,请立即跳过此示例。 以下调用方法看起来更有效:


 Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4 

因此,让我们计算一下分配一块内存所需的次数:


  • email.Normalize()导致某种对象的创建。 因此,此对象将分配在堆上(或分配在堆栈上-没关系,因为装箱将需要选择堆上的所有对象)
  • 正如我们之前所考虑的, id将进入一个堆。
  • Log4net具有以下用于此类长格式调用的接口: void DebugFormat(string format, params object[] args) 。 如您所见,.Net将在堆上创建一个数组,以将其传递给DebugFormat方法。

结果,对日志记录操作的相当典型的调用将导致在内存中创建对象堆。 令人失望的是,因为日志记录本身经常被关闭。 但是,让我们继续进行NLog。


这行将引起对象在堆上的分配:


 NLogLog.Debug($"Id={id}"); 

这里的一切都很明显,但是下面的行不再有这样的缺点:


 NLogLog.Debug("Id={0}", id); 

原因是NLog对int有一个特殊的签名: void Debug(string message, int argument) 。 此外,即使您传输其他结构, void Debug<TArgument>([Localizable(false)] string message, TArgument argument) 。 而且此方法不需要装箱,因为在JIT之后将为每种类型创建一个单独的函数(当然,这并不完全正确,但重要的一点是:不会装箱)。


我将跳过带有大输入行的易于理解的脚本,然后直接转到:


 NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); 

奇怪的是,NLog并未增加方法的泛型参数的数量,因此将使用签名: void Debug([Localizable(false)] string message, params object[] args) 。 它将再次导致在堆中创建对象等。


结论与改进


主要结论:如果您对程序中的日志记录方法进行了很多调用而没有导致对文件的物理写入,那么您可以从头开始,在堆上分配很多不必要的对象。 从而抑制了程序的工作。


结论2:如果将很多对象传递给方法,请使用NLog。 由于它照顾了Generic参数,因此您可以放宽性能。


但是,为了完全安全,这样做是更合乎逻辑的:


 if (NLogLog.IsDebugEnabled) { NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); } 

如果没有必要,此处将不调用日志记录方法。 但是,如果仍然必须将数据转储到日志中,则将使用方便的String Interpolation。 在内部,记录器(至少具有相同的NLog)进行了优化,可以直接在日志中写入一行(即,格式化将立即在Stream ,而不是在内存中创建一行)。 但是,由于必须将数据重置为文件,因此对NLog的优化逐渐消失。


Kotlin示例


为了淡化.Net中流行记录器的工作描述,我将提供一种有趣的方式来将调用包装在kotlin中。 这个想法实际上是基于该语言的一个有趣特征: 内联方法 。 因此,一个简单的代码输出一些要调试的东西:


 class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { "Identity: $id" } } } 

它将由编译器转换为如下形式:


 class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val message = "Identity: $id" logger.debug(message) }catch (e: Exception){ /*handle*/ } } } } 

在这里很重要: debug括号内的所有内容都是lambda。 但是,它将嵌入在您的方法中,也就是说,不会在堆中创建函数对象。 因此,您可以在其中隐藏大型操作,仅当您要将结果输出到debug才会调用这些操作。 例如:


 class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { val idList = getIdList() "Identity: $idList" } } } 

仅当您需要向文件发送getIdList才会调用getIdList 。 都是因为代码被转换为:


 class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val idList = getIdList() val message = "Identity: $idList" logger.debug(message) }catch (){ /*handle*/ } } logger.debug { "Identity: $id" } } } 

大对象==>大对象堆


除了前面的示例。 我确信很多人都知道.Net / JVM具有“大对象堆”的概念。 更准确地说,Java中没有特殊定义,但是,分配器通常会在最新一代中立即创建大型对象(以最大程度地减少对象的移动并解决流式分配器的快速内存渗透问题)。


回到示例:


 NLogLog.Debug($"Id={id}"); 

如您所知,如果id对象具有ToString的实现,该实现创建了一个兆字节大小的字符串,则LOH界面中将出现以下情况:


  • ToString本身
  • 格式化$"Id={id}"
  • 而且如果记录器的开发人员没有抓住所有这些事情(并且为LOH中缺少对象编写测试非常困难),那么记录器将增加问题。

在这里,您可以使用三种方法记录此类事件:


  • 使用特殊的布局,不需要调用ToString 。 例如,NLog具有JsonLayout 。 因此,您可以简单地将一个对象传输到记录器,该对象将立即序列化到结果流(例如,文件)。
  • 自己写入文件。 换句话说-不要使用记录仪。 我只能自行建议如何找出NLog将写入哪个文件: var filePath = NLog.LogManager.Configuration.AllTargets.OfType<FileTarget>().First().FileName.Render(LogEventInfo.CreateNullEvent()) 。 显然,此函数将返回遇到的第一个FileTarget ,但是如果每个人都写入同一文件夹,则可以通过类似的方式找出要记录的文件夹,然后将对象的转储直接发送到该文件。
  • 如果您有log4j2(第二个很重要),则可以使用StringBuilderFormattable 。 创建它的目的是为了将数据分段输出到记录器中(此外,为了不将部分分段分配到堆中,因为已经选择了它们)。

 public interface StringBuilderFormattable { /** * Writes a text representation of this object into the specified {@code StringBuilder}, ideally without allocating * temporary objects. * * @param buffer the StringBuilder to write into */ void formatTo(StringBuilder buffer); } 

同步(和异步问题)


一次,在一个程序中,我注意到在加载操作期间,大约一半的UI等待时间是由日志记录操作所占。 再一次:程序的一半时间都花在了调用logger.Debug或类似的事情上。 这样做的原因很简单:我们使用了log4net,它只能同步写入文件。


从这里我推导出规则1 :记录器应始终在另一个线程中工作。 您不应该为了跟踪而阻塞应用程序代码,因为它非常奇怪。 换句话说-使用NLog-您总是需要在nlog标记中放入async=true (这是主要标记)。 或者,如示例所示


 <targets async="true"> ... your targets go here ... </targets> 

如果您使用log4net,则可以从它重定向到NLog,或使用AsyncFileAppender。


对于Java世界:Logback和Log4J2都可以执行异步日志记录。 这是官方网站的比较:


图片


但是,当所有内容都是异步写入时,会出现另一个问题-发生严重错误时该怎么办? 毕竟,由于离开了Main线程而导致程序没有退出(例如,程序可以通过调用Application.ExitEnvironment.FailFast退出,虽然它不是很漂亮,但是确实会发生)。 在这种情况下,必须在终止进程之前始终调用Flush 。 否则,如果您落在战斗服务器上,则将丢失最有价值的信息。


结论


我希望本文可以帮助您编写具有方便日志记录的快速程序。 我只强调了部分在代码中看到的问题。 所有这些都不是最明显的,但也不是最困难的。


无论如何,就像我一开始所说的那样,几乎在每个应用程序中都使用记录器。 而且,根据我的笔记,大约一半的类本身将某些内容输出到日志中。 因此,使用这些功能的正确操作几乎会影响整个应用程序。

Source: https://habr.com/ru/post/zh-CN458436/


All Articles