為什么生產(chǎn)日志無(wú)法幫助您找到錯(cuò)誤的真正根本原因？

詢問(wèn)您是否使用日志文件監(jiān)視您的應(yīng)用程序幾乎就像詢問(wèn)…您是否喝水。 我們都使用日志，但是我們?nèi)绾问褂盟鼈儎t是一個(gè)完全不同的問(wèn)題。

在下面的文章中，我們將對(duì)日志進(jìn)行更深入的研究，并了解日志的用法和向日志中寫入的內(nèi)容。 我們走吧。

我們的研發(fā)團(tuán)隊(duì)對(duì)Aviv Danziger表示了極大的幫助，感謝他為我們提供和處理數(shù)據(jù)的巨大幫助。

基礎(chǔ)工作

我們尋求答案需要大量數(shù)據(jù)，因此我們選擇了Google BigQuery。 幾個(gè)月前，我們首次使用它來(lái)查看GitHub的頂級(jí)Java項(xiàng)目如何使用logs 。

對(duì)于我們當(dāng)前的帖子，我們?cè)贕itHub上排名前40萬(wàn)的Java存儲(chǔ)庫(kù)中，按它們?cè)?016年獲得的星級(jí)排名進(jìn)行了排名。在這些存儲(chǔ)庫(kù)中，我們過(guò)濾掉了Android，示例項(xiàng)目和簡(jiǎn)單的測(cè)試程序，從而為我們提供了15797個(gè)存儲(chǔ)庫(kù)。

然后，我們提取了包含100多個(gè)日志記錄語(yǔ)句的存儲(chǔ)庫(kù)，這給我們留下了1,463個(gè)存儲(chǔ)庫(kù)可以使用。 現(xiàn)在，是時(shí)候?yàn)樗惺刮覀儚匾闺y眠的問(wèn)題找到答案的時(shí)候了。

TL; DR：主要要點(diǎn)

如果您不喜歡餅圖，柱形圖或條形圖，并且想跳過(guò)主要課程而直接進(jìn)入甜點(diǎn)，那么以下是我們了解的關(guān)于日志記錄及其實(shí)際操作的5個(gè)關(guān)鍵點(diǎn)：

1.日志實(shí)際上并沒有我們想像的那么多，即使它們每天最多可以增加數(shù)百GB。 超過(guò)50％的語(yǔ)句沒有有關(guān)應(yīng)用程序可變狀態(tài)的信息
2.在生產(chǎn)中，禁用了全部日志記錄語(yǔ)句的64％
3.達(dá)到生產(chǎn)狀態(tài)的日志記錄語(yǔ)句的變量比平均開發(fā)水平的日志記錄語(yǔ)句少35％ 4. “永遠(yuǎn)不要發(fā)生” 5.有一種更好的方法來(lái)解決生產(chǎn)中的錯(cuò)誤

現(xiàn)在，讓我們用一些數(shù)據(jù)備份這些點(diǎn)。

1.多少個(gè)記錄語(yǔ)句實(shí)際上包含變量？

我們要檢查的第一件事是每個(gè)語(yǔ)句中發(fā)出了多少個(gè)變量。 我們選擇在每個(gè)存儲(chǔ)庫(kù)中按從0個(gè)變量到5個(gè)及以上的比例對(duì)數(shù)據(jù)進(jìn)行切片。 然后，我們對(duì)總數(shù)進(jìn)行了計(jì)算，并對(duì)研究中所有項(xiàng)目的平均細(xì)分情況有所了解。

按變量數(shù)計(jì)算的平均Java項(xiàng)目

如您所見，普通的Java項(xiàng)目不會(huì)在其日志記錄語(yǔ)句的50％以上記錄任何變量。 我們還可以看到，只有0.95％的日志記錄語(yǔ)句發(fā)出5個(gè)或更多變量。

這意味著日志所捕獲的有關(guān)應(yīng)用程序的信息有限，而找出實(shí)際發(fā)生的情況可能就像在日志文件中搜索針頭一樣。

2.生產(chǎn)中激活了多少個(gè)記錄語(yǔ)句？

開發(fā)和生產(chǎn)環(huán)境有所不同，原因有很多，其中之一就是它們與日志記錄的關(guān)系。 在開發(fā)中，所有日志級(jí)別均已激活。 但是，在生產(chǎn)中僅會(huì)激活ERROR和WARN。 讓我們看看這種分解是什么樣的。

生產(chǎn)與開發(fā)日志

該圖表顯示，普通的Java應(yīng)用程序具有35.5％的唯一日志記錄語(yǔ)句，這些語(yǔ)句有可能在生產(chǎn)中被激活（ERROR，WARN），以及64.5％的語(yǔ)句僅在開發(fā)中被激活（TRACE，INFO，DEBUG）。

大多數(shù)信息丟失。 哎喲。

3.每個(gè)日志級(jí)別的平均變量數(shù)是多少？

因此，開發(fā)人員不僅會(huì)跳過(guò)語(yǔ)句中的變量，而且普通的Java應(yīng)用程序首先不會(huì)向生產(chǎn)日志發(fā)送那么多的語(yǔ)句。

現(xiàn)在，我們決定分別查看每個(gè)日志級(jí)別，并計(jì)算相應(yīng)語(yǔ)句中變量的平均數(shù)量。

每個(gè)記錄語(yǔ)句的平均變量數(shù)

平均值表明，TRACE，DEBUG和INFO語(yǔ)句比WARN和ERROR包含更多的變量。 考慮到前三個(gè)變量的平均數(shù)量是0.78，而后兩個(gè)變量的平均數(shù)量是0.5，“更多”是一個(gè)禮貌的單詞。

這意味著生產(chǎn)日志記錄語(yǔ)句包含的變量比開發(fā)日志記錄語(yǔ)句少35％。 另外，正如我們前面所看到的，它們的總數(shù)也要低得多。

如果要在日志中搜索有關(guān)您的應(yīng)用程序發(fā)生了什么的線索，但顯示為空白–這就是它發(fā)生的原因。 不用擔(dān)心，有更好的方法。

通過(guò)OverOps ，您可以查看任何異常，記錄的錯(cuò)誤或警告背后的變量，而無(wú)需依賴實(shí)際記錄的信息。 您將能夠在事件的整個(gè)調(diào)用堆棧中查看完整的源代碼和變量狀態(tài)。 即使未將其打印到日志文件中。 OverOps還向您顯示250條在錯(cuò)誤之前記錄的DEBUG，TRACE和INFO級(jí)別的語(yǔ)句，即使它們已關(guān)閉并且從未到達(dá)日志文件，也正在生產(chǎn)中。

我們很樂(lè)意向您展示其工作原理， 請(qǐng)點(diǎn)擊此處安排演示 。

4.這永遠(yuǎn)不會(huì)發(fā)生

由于我們已經(jīng)掌握了所有這些日志記錄語(yǔ)句的信息，因此我們決定從中獲得一些樂(lè)趣。 我們發(fā)現(xiàn)有58條提及“這絕不應(yīng)該發(fā)生”。

我們只能說(shuō)，如果它永遠(yuǎn)不會(huì)發(fā)生，則至少要有一個(gè)體面才能打印出一個(gè)變量或2，因此您將能夠看到它為什么仍會(huì)發(fā)生＆＃55357;＆＃56898;

我們是如何做到的？

如前所述，要獲取此數(shù)據(jù)，我們首先必須過(guò)濾掉不相關(guān)的Java存儲(chǔ)庫(kù)，然后將重點(diǎn)放在具有超過(guò)100個(gè)日志記錄語(yǔ)句的存儲(chǔ)庫(kù)上，這給我們留下了1,463個(gè)存儲(chǔ)庫(kù)。

然后，我們添加了一些正則表達(dá)式魔術(shù)，并刪除了所有日志行：

SELECT *FROM [java-log-levels-usage:java_log_level_usage.top_repos_java_contents_lines_no_android_no_arduino]WHERE REGEXP_MATCH(line, r'.*((LOGGER|Logger|logger|LOG|Log|log)[.](trace|info|debug|warn|warning|error|fatal|severe|config|fine|finer|finest)).*')OR REGEXP_MATCH(line, r'.*((Level|Priority)[.](TRACE|TRACE_INT|X_TRACE_INT|INFO|INFO_INT|DEBUG|DEBUG_INT|WARN|WARN_INT|WARNING|WARNING_INT|ERROR|ERROR_INT)).*')OR REGEXP_MATCH(line, r'.*((Level|Priority)[.](FATAL|FATAL_INT|SEVERE|SEVERE_INT|CONFIG|CONFIG_INT|FINE|FINE_INT|FINER|FINER_INT|FINEST|FINEST_INT|ALL|OFF)).*')

現(xiàn)在我們有了數(shù)據(jù)，我們開始對(duì)其進(jìn)行切片。 首先，我們篩選出每個(gè)日志級(jí)別的變量數(shù)量：

SELECT sample_repo_name,log_level,CASE WHEN parametersCount + concatenationCount = 0 THEN "0"WHEN parametersCount + concatenationCount = 1 THEN "1"WHEN parametersCount + concatenationCount = 2 THEN "2"WHEN parametersCount + concatenationCount = 3 THEN "3"WHEN parametersCount + concatenationCount = 4 THEN "4"WHEN parametersCount + concatenationCount >= 5 THEN "5+"END total_params_tier,SUM(parametersCount + concatenationCount) total_params,SUM(CASE WHEN parametersCount > 0 THEN 1 ELSE 0 END) has_parameters,SUM(CASE WHEN concatenationCount > 0 THEN 1 ELSE 0 END) has_concatenation,SUM(CASE WHEN parametersCount = 0 AND concatenationCount = 0 THEN 1 ELSE 0 END) has_none,SUM(CASE WHEN parametersCount > 0 AND concatenationCount > 0 THEN 1 ELSE 0 END) has_both,COUNT(1) logging_statements,SUM(parametersCount) parameters_count,SUM(concatenationCount) concatenation_count,SUM(CASE WHEN isComment = true THEN 1 ELSE 0 END) comment_count,SUM(CASE WHEN shouldNeverHappen = true THEN 1 ELSE 0 END) should_never_happen_countFROM [java-log-levels-usage:java_log_level_usage.top_repos_java_log_lines_no_android_no_arduino_attributes] GROUP BY sample_repo_name,log_level,total_params_tier

然后計(jì)算每個(gè)層的平均使用量。 這就是我們獲得總存儲(chǔ)庫(kù)語(yǔ)句的平均百分比的方式。

SELECT total_params_tier,AVG(logging_statements / total_repo_logging_statements) percent_out_of_total_repo_statements,SUM(total_params) total_params,SUM(logging_statements) logging_statements,SUM(has_parameters) has_parameters,SUM(has_concatenation) has_concatenation,SUM(has_none) has_none,SUM(has_both) has_both,SUM(parameters_count) parameters_count,SUM(concatenation_count) concatenation_count,SUM(comment_count) comment_count,SUM(should_never_happen_count) should_never_happen_countFROM (SELECT sample_repo_name,total_params_tier,SUM(total_params) total_params,SUM(logging_statements) logging_statements,SUM(logging_statements) OVER (PARTITION BY sample_repo_name) total_repo_logging_statements,SUM(has_parameters) has_parameters,SUM(has_concatenation) has_concatenation,SUM(has_none) has_none,SUM(has_both) has_both,SUM(parameters_count) parameters_count,SUM(concatenation_count) concatenation_count,SUM(comment_count) comment_count,SUM(should_never_happen_count) should_never_happen_countFROM [java-log-levels-usage:java_log_level_usage.top_repos_java_log_lines_no_android_no_arduino_attributes_counters_with_params_count]GROUP BY sample_repo_name,total_params_tier)WHERE total_repo_logging_statements >= 100GROUP BY total_params_tierORDER BY 1,2

您可以在我們的原始數(shù)據(jù)文件中查看計(jì)算結(jié)果 。

最后的想法

我們都使用日志文件，但是似乎大多數(shù)人都認(rèn)為它們是理所當(dāng)然的。 有了眾多的日志管理工具，我們忘記了控制我們自己的代碼-并使它對(duì)于我們理解，調(diào)試和修復(fù)很有意義。

翻譯自: https://www.javacodegeeks.com/2017/02/github-research-50-java-logging-statements-written-wrong.html

總結(jié)

以上是生活随笔為你收集整理的GitHub Research：超过50％的Java记录语句写错了的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問(wèn)題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。