2

我可以使用一些帮助来优化一些 Common Lisp 代码。我正在尝试从日志文件中查询数据。从超过 14.5k 行中提取前 50 行需要一秒钟。推断出来，从日志文件中读取数据大约需要 5 分钟。此外，当整个文件只有 14MB 时，我当前实现的前 50 行分配了 ~50MB。我想要这样做的是对数据执行 1 次读取，以使用最少数量的内存分配对其进行解析。

我知道我看到的性能下降是由于我的代码。我很难思考如何重构我的代码以尽量减少我看到的问题。我尝试使用 WITH-INPUT-FROM-STRING 将字符串作为流访问，并且性能没有明显变化。

这是一个 IIS 日志，因此它具有一致的结构。前 2 个字段是日期和时间，我想将其解析为一个数字，以便在需要时限制数据范围。之后，大部分字段的大小都是可变的，但都用空格分隔。

使用我的代码：使用 8 个可用 CPU 内核运行需要 1,138,000 微秒（1.138000 秒）。在此期间，在用户模式下花费了 1,138,807 微秒（1.138807 秒），在系统模式下花费了 0 微秒（0.000000 秒），在 GC 中花费了 19,004 微秒（0.019004 秒）。分配了 49,249,040 字节的内存。

没有我的代码：使用 8 个可用 CPU 内核运行需要 64,000 微秒（0.064000 秒）。在此期间，在用户模式下花费了 62,401 微秒（0.062401 秒），在系统模式下花费了 0 微秒（0.000000 秒），分配了 834,512 字节的内存。

(defun read-date-time (hit)
  (let ((date-time (chronicity:parse (subseq hit 0 20))))
    (encode-universal-time (chronicity:sec-of date-time)
               (chronicity:minute-of date-time)
               (chronicity:hour-of date-time)
               (chronicity:day-of date-time)
               (chronicity:month-of date-time)
               (chronicity:year-of date-time))))

(defun parse-hit (hit)
  (unless (eq hit :eof)
    (cons (read-date-time hit)
          (split-sequence:split-sequence #\Space (subseq hit 20)))))


(time (gzip-stream:with-open-gzip-file (ins "C:\\temp\\test.log.gz") 
  (read-line ins nil :eof)
  (loop for i upto 50 
     do (parse-hit (read-line ins nil :eof)))))

我的第一次尝试是一种非常幼稚的方法，我认识到我的代码现在可以使用一些改进，所以我要求一些方向。如果教程更适合回答此问题，请发布链接。我喜欢

4

3 回答 3

3

问题是 Chronicity 包，它在内部使用了 Local Time 包。

这个：

   (encode-universal-time (chronicity:sec-of date-time)
           (chronicity:minute-of date-time)
           (chronicity:hour-of date-time)
           (chronicity:day-of date-time)
           (chronicity:month-of date-time)
           (chronicity:year-of date-time))))

正在压垮你。

chronicity:month-of来电local-time:timestamp-month。如果您查看该代码：

 (nth-value 1
         (%timestamp-decode-date
          (nth-value 1 (%adjust-to-timezone timestamp timezone))))

所以，这里是解码基本日期（看起来是一个整数），两次，（一次用于时区，另一次用于月份。

所以你在解码同一个日期，做同样的工作，每个日期 6 次。而这些惯例正在引发一场风暴。

您还调用了 subseq 两次。

因此，在我看来，在这种情况下，您需要专注于日期解析逻辑，使用不那么通用的东西。您无需验证日期（假定日志是准确的），也无需转换为自纪元以来的天/秒/毫秒，您只需要单独的 MDY、HMS 数据。您正在使用当前软件包完成所有这些工作，一旦您创建了通用时间，它就变得多余了。

您也可能不关心时区。

无论如何，这是问题所在的开始。这还不是 I/O 问题。

于 2013-10-19T22:34:47.873 回答
0

我对代码进行了一些修改，并减少了执行时间和显着分配的字节数。

新代码：使用 8 个可用 CPU 内核运行 65,000 微秒（0.065000 秒）。在此期间，在用户模式下花费了 62,400 微秒（0.062400 秒），在系统模式下花费了 0 微秒（0.000000 秒），在 GC 中花费了 2,001 微秒（0.002001 秒）。分配了 1,029,024 字节的内存。

(let ((date-time-string (make-array 20 :initial-element nil)))
  (defun read-date-time (hit)
    (read-sequence date-time-string hit :start 0 :end 20)
    (local-time:timestamp-to-universal (local-time:parse-timestring (map 'string #'code-char date-time-string) :date-time-separator #\Space))))

(defun parse-hit (hit)
  (cons (read-date-time hit) (split-sequence:split-sequence #\Space (read-line hit))))

(defun timeparse (lines)
  (time (gzip-stream:with-open-gzip-file (ins "C:\\temp\\test.log.gz")
      (read-line ins nil :eof) 
      (loop for i upto lines
         do (parse-hit ins)))))

解压缩的文件为 14MB，其中包含大约 14.5k 行。

解析文件的 10k 行会在 8.5 秒内分配 178MB。我相信这与 gzip-stream 库或其依赖项之一有关。

无需解析，仅对压缩文件中的 10k 行执行读取行需要 8 秒并分配 140MB 内存。

如果不进行解析，只需在未压缩文件的相同 10k 行上执行读取行大约需要 1/10 秒，并且仅分配 28MB。

我现在对 gzip-stream 的性能无能为力，所以我将不得不忍受它，直到性能不再可以忍受。

谢谢大家的帮助和建议。

于 2013-10-21T18:33:14.883 回答
0

例如，这是我尝试过的东西，而不是完整的日志解析器，当然您可以选择以不同的方式表示数据/选择对您重要的内容，这只是一般的想法：

(defparameter *log*
  "2012-11-04 23:00:04 10.1.151.54 GET /_layouts/1033/js/global.js v=5 443 - 10.1.151.61 Mozilla/5.0+(Windows+NT+6.1)+AppleWebKit/535.2+(KHTML,+like+Gecko)+Chrome/15.0.864.0+Safari/535.2 200 0 0 31
2012-11-04 23:00:04 10.1.151.54 GET /_layouts/1033/styles/css/topnav.css v=1 443 - 10.1.151.61 Mozilla/5.0+(Windows+NT+6.1)+AppleWebKit/535.2+(KHTML,+like+Gecko)+Chrome/15.0.864.0+Safari/535.2 200 0 0 62
2012-11-04 23:00:07 10.1.151.54 GET /pages/index.aspx - 80 - 10.1.151.59 - 200 0 64 374
2012-11-04 23:00:07 10.1.151.52 GET /pages/index.aspx - 80 - 10.1.151.59 - 200 0 64 374")

(defstruct iis-log-entry
  year month day hour minute second ip method path)

(defstruct ipv4 byte-0 byte-1 byte-2 byte-3)

(defun parse-ipv4 (entry &key start end)
  (let* ((b0 (position #\. entry))
         (b1 (position #\. entry :start (1+ b0)))
         (b2 (position #\. entry :start (1+ b1))))
    (make-ipv4
     :byte-0 (parse-integer entry :start start :end b0)
     :byte-1 (parse-integer entry :start (1+ b0) :end b1)
     :byte-2 (parse-integer entry :start (1+ b1) :end b2)
     :byte-3 (parse-integer entry :start (1+ b2) :end end))))

(defun parse-method (entry &key start end)
  ;; this can be extended to make use of END argument and other
  ;; HTTP verbs
  (case (char entry start)
    (#\G 'get)
    (#\P (case (char entry (1+ start))
           (#\O 'post)
           (#\U 'put)))))

(defun parse-path (entry &key start) (subseq entry start))

(defun parse-iis-log-entry (entry)
  (let* ((ip-end (position #\Space entry :start 27))
         (method-end (position #\Space entry :start ip-end)))
    (make-iis-log-entry
     :year (parse-integer entry :start 0 :end 4)
     :month (parse-integer entry :start 5 :end 7)
     :day (parse-integer entry :start 8 :end 10)
     :hour (parse-integer entry :start 11 :end 13)
     :minute (parse-integer entry :start 14 :end 16)
     :second (parse-integer entry :start 17 :end 19)
     :ip (parse-ipv4 entry :start 20 :end ip-end)
     :method (parse-method entry :start (1+ ip-end) :end method-end)
     :path (parse-path entry :start method-end))))

(defun test ()
  (time
   (loop :repeat 50000 :do
      (with-input-from-string (stream *log*)
        (loop
           :for line := (read-line stream nil nil)
           :while line
           :for record := (parse-iis-log-entry line))))))

(test)
;; Evaluation took:
;;   0.790 seconds of real time
;;   0.794000 seconds of total run time (0.792000 user, 0.002000 system)
;;   [ Run times consist of 0.041 seconds GC time, and 0.753 seconds non-GC time. ]
;;   100.51% CPU
;;   1,733,036,566 processor cycles
;;   484,002,144 bytes consed

此外，当然，您可以使用一些宏来减少parse-*函数的重复位。

于 2013-10-20T09:45:01.197 回答