From dab3e40a3b30671d41fc03074f7db7477f8cfe63 Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Fri, 3 Jul 2020 23:41:17 +0800 Subject: [PATCH 01/19] support to handle invalid logs in the file beginning and end --- search_log.go | 74 +++++++++++++++++++++++++++++++++++----------- search_log_test.go | 4 +++ 2 files changed, 61 insertions(+), 17 deletions(-) diff --git a/search_log.go b/search_log.go index fde4f91..c902b48 100644 --- a/search_log.go +++ b/search_log.go @@ -73,31 +73,25 @@ func resolveFiles(logFilePath string, beginTime, endTime int64) ([]logFile, erro return nil } reader := bufio.NewReader(file) - // Skip this file if cannot read the first line - firstLine, err := readLine(reader) - if err != nil && err != io.EOF { - skipFiles = append(skipFiles, file) - return nil - } - // Skip this file if the first line is not a valid log message - firstItem, err := parseLogItem(firstLine) + + firstItem, err := readFirstValidLog(reader, 0) if err != nil { skipFiles = append(skipFiles, file) return nil } - // Skip this file if cannot read the last line - lastLine := readLastLine(file) - // Skip this file if the last line is not a valid log message - lastItem, err := parseLogItem(lastLine) + + lastItem, err := readLastValidLog(file, 0) if err != nil { skipFiles = append(skipFiles, file) return nil } + // Reset position to the start and skip this file if cannot seek to start if _, err := file.Seek(0, io.SeekStart); err != nil { skipFiles = append(skipFiles, file) return nil } + if beginTime > lastItem.Time || endTime < firstItem.Time { skipFiles = append(skipFiles, file) } else { @@ -109,11 +103,13 @@ func resolveFiles(logFilePath string, beginTime, endTime int64) ([]logFile, erro } return nil }) + defer func() { for _, f := range skipFiles { _ = f.Close() } }() + // Sort by start time sort.Slice(logFiles, func(i, j int) bool { return logFiles[i].begin < logFiles[j].begin @@ -121,6 +117,49 @@ func resolveFiles(logFilePath string, beginTime, endTime int64) ([]logFile, erro return logFiles, err } +// parameter tryLines: if value is 0, means unlimited +func readFirstValidLog(reader *bufio.Reader, tryLines int64) (*pb.LogMessage, error) { + var tried int64 + for { + line, err := readLine(reader) + if err != nil { + return nil, err + } + item, err := parseLogItem(line) + if err == nil { + return item, nil + } + tried++ + if tryLines > 0 && tried >= tryLines { + break + } + } + return nil, errors.New("not a valid log file") +} + +// parameter tryLines: if value is 0, means unlimited +func readLastValidLog(file *os.File, tryLines int64) (*pb.LogMessage, error) { + var tried int64 + var endCursor int64 + for { + line := readLineReverse(file, endCursor) + // read out the file + if len(line) == 0 { + break + } + endCursor -= int64(len(line)) + item, err := parseLogItem(line) + if err == nil { + return item, nil + } + tried++ + if tryLines > 0 && tried >= tryLines { + break + } + } + return nil, errors.New("not a valid log file") +} + // Read a line from a reader. func readLine(reader *bufio.Reader) (string, error) { var line, b []byte @@ -136,20 +175,21 @@ func readLine(reader *bufio.Reader) (string, error) { return string(line), nil } -func readLastLine(file *os.File) string { +// Read a line from the end of a file. +func readLineReverse(file *os.File, endCursor int64) string { var line []byte - var cursor int64 + var cursor = endCursor stat, _ := file.Stat() filesize := stat.Size() for { - cursor -= 1 + cursor-- file.Seek(cursor, io.SeekEnd) char := make([]byte, 1) file.Read(char) // stop if we find a line - if cursor != -1 && (char[0] == 10 || char[0] == 13) { + if cursor != endCursor-1 && (char[0] == 10 || char[0] == 13) { break } line = append(line, char[0]) @@ -163,7 +203,7 @@ func readLastLine(file *os.File) string { return string(line) } -// Returns LogLevel from string and return LogLevel_Info if +// ParseLogLevel returns LogLevel from string and return LogLevel_Info if // the string is an invalid level string func ParseLogLevel(s string) pb.LogLevel { switch s { diff --git a/search_log_test.go b/search_log_test.go index 1af5155..d8cbbcc 100644 --- a/search_log_test.go +++ b/search_log_test.go @@ -73,11 +73,15 @@ func (s *searchLogSuite) writeTmpFile(c *C, filename string, lines []string) { func (s *searchLogSuite) TestResoveFiles(c *C) { s.writeTmpFile(c, "tidb.log", []string{ + `20/08/26 06:19:13.011 -04:00 [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `hello TiDB`, `[2019/08/26 06:19:13.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `20/08/26 06:19:13.011 -04:00 [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `hello TiDB`, }) // single line file From d2fbf9ccdf99b489e8bf7a84c88cd6a4499dbb23 Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Mon, 6 Jul 2020 11:15:49 +0800 Subject: [PATCH 02/19] support invalid log in the middle of log file --- search_log.go | 19 +++++++++++++------ service.go | 13 ++++++++++++- 2 files changed, 25 insertions(+), 7 deletions(-) diff --git a/search_log.go b/search_log.go index c902b48..4be94cb 100644 --- a/search_log.go +++ b/search_log.go @@ -176,6 +176,7 @@ func readLine(reader *bufio.Reader) (string, error) { } // Read a line from the end of a file. +// TODO: byte by byte read is low effiency, we can improve it func readLineReverse(file *os.File, endCursor int64) string { var line []byte var cursor = endCursor @@ -314,21 +315,27 @@ nextLine: iter.reader.Reset(iter.pending[iter.fileIndex]) continue } - if len(line) < len(TimeStampLayout) { + line = strings.TrimSpace(line) + if len(line) == 0 { continue } - // Skip invalid log item item, err := parseLogItem(line) if err != nil { - continue + // handle invalid log + // make whole line as log message with 0 time and 0 level + item = &pb.LogMessage{ + Time: 0, + Level: 0, + Message: line, + } } - if item.Time > iter.end { + if item.Time > 0 && item.Time > iter.end { return nil, io.EOF } - if item.Time < iter.begin { + if item.Time > 0 && item.Time < iter.begin { continue } - if iter.levelFlag != 0 && iter.levelFlag&(1<<item.Level) == 0 { + if item.Level > 0 && iter.levelFlag != 0 && iter.levelFlag&(1<<item.Level) == 0 { continue } if len(iter.patterns) > 0 { diff --git a/service.go b/service.go index be3d633..8ac396f 100644 --- a/service.go +++ b/service.go @@ -73,18 +73,29 @@ func (d *DiagnosticsServer) SearchLog(req *pb.SearchLogRequest, stream pb.Diagno } defer iter.close() + var preMessage *pb.LogMessage for { var messages []*pb.LogMessage var drained bool for i := 0; i < 1024; i++ { item, err := iter.next() - if err != nil && err == io.EOF { + if err == io.EOF { drained = true break } if err != nil { return err } + // invalid log + if item.Time == 0 { + if preMessage == nil { + continue + } + // use the previous message's time and level + item.Time = preMessage.Time + item.Level = preMessage.Level + } + preMessage = item messages = append(messages, item) } res := &pb.SearchLogResponse{ From ca397ce41884c362ddddc605aeccb68a0b8e4f5b Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Mon, 6 Jul 2020 11:43:48 +0800 Subject: [PATCH 03/19] refine --- search_log.go | 19 +++++++++++++------ service.go | 11 ----------- 2 files changed, 13 insertions(+), 17 deletions(-) diff --git a/search_log.go b/search_log.go index 4be94cb..738f68a 100644 --- a/search_log.go +++ b/search_log.go @@ -285,6 +285,7 @@ type logIterator struct { fileIndex int reader *bufio.Reader pending []*os.File + preTime int64 } // The Close method close all resources the iterator has. @@ -321,21 +322,27 @@ nextLine: } item, err := parseLogItem(line) if err != nil { + if iter.preTime == 0 { + continue + } // handle invalid log - // make whole line as log message with 0 time and 0 level + // make whole line as log message with pre time and unknown log_level item = &pb.LogMessage{ - Time: 0, - Level: 0, + Time: iter.preTime, + Level: pb.LogLevel_UNKNOWN, Message: line, } + } else { + iter.preTime = item.Time } - if item.Time > 0 && item.Time > iter.end { + if item.Time > iter.end { return nil, io.EOF } - if item.Time > 0 && item.Time < iter.begin { + if item.Time < iter.begin { continue } - if item.Level > 0 && iter.levelFlag != 0 && iter.levelFlag&(1<<item.Level) == 0 { + // always keep unknown log_level + if item.Level > pb.LogLevel_UNKNOWN && iter.levelFlag != 0 && iter.levelFlag&(1<<item.Level) == 0 { continue } if len(iter.patterns) > 0 { diff --git a/service.go b/service.go index 8ac396f..4abc0a3 100644 --- a/service.go +++ b/service.go @@ -73,7 +73,6 @@ func (d *DiagnosticsServer) SearchLog(req *pb.SearchLogRequest, stream pb.Diagno } defer iter.close() - var preMessage *pb.LogMessage for { var messages []*pb.LogMessage var drained bool @@ -86,16 +85,6 @@ func (d *DiagnosticsServer) SearchLog(req *pb.SearchLogRequest, stream pb.Diagno if err != nil { return err } - // invalid log - if item.Time == 0 { - if preMessage == nil { - continue - } - // use the previous message's time and level - item.Time = preMessage.Time - item.Level = preMessage.Level - } - preMessage = item messages = append(messages, item) } res := &pb.SearchLogResponse{ From e1084ade75e42b4613e231da08c0a70ded321309 Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Mon, 6 Jul 2020 12:10:08 +0800 Subject: [PATCH 04/19] update test --- search_log_test.go | 22 ++++++++++++++++++++++ 1 file changed, 22 insertions(+) diff --git a/search_log_test.go b/search_log_test.go index d8cbbcc..5a2860f 100644 --- a/search_log_test.go +++ b/search_log_test.go @@ -213,6 +213,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, + `This is an invalid log blablabla`, `[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`, }) @@ -231,6 +232,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { s.writeTmpFile(c, "rpc.tidb-3.log", []string{``}) s.writeTmpFile(c, "rpc.tidb-4.log", []string{ `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `This is also an invalid log contains partern ...`, `[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, @@ -258,11 +260,13 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, `[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:20:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, `[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, @@ -277,11 +281,13 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, `[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:20:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, `[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, @@ -298,6 +304,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, `[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`, }, }, @@ -309,6 +316,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, `[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, @@ -323,11 +331,13 @@ func (s *searchLogSuite) TestLogIterator(c *C) { expect: []string{ `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, `[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:20:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, `[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, }, }, @@ -346,6 +356,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, }, }, // 7 @@ -355,6 +366,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, }, }, // 8 @@ -363,6 +375,8 @@ func (s *searchLogSuite) TestLogIterator(c *C) { levels: []pb.LogLevel{pb.LogLevel_Debug}, expect: []string{ `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, + `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, }, }, // 9 @@ -370,7 +384,9 @@ func (s *searchLogSuite) TestLogIterator(c *C) { search: timeRange{"2019/08/26 06:19:15.011 -04:00", "2019/08/26 06:22:14.011 -04:00"}, levels: []pb.LogLevel{pb.LogLevel_Trace}, expect: []string{ + `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, `[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, }, }, // 10 @@ -378,9 +394,11 @@ func (s *searchLogSuite) TestLogIterator(c *C) { search: timeRange{"2019/08/26 06:19:15.011 -04:00", "2019/08/26 06:22:14.011 -04:00"}, levels: []pb.LogLevel{pb.LogLevel_Info}, expect: []string{ + `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, `[2019/08/26 06:20:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, }, }, // 11 @@ -388,7 +406,9 @@ func (s *searchLogSuite) TestLogIterator(c *C) { search: timeRange{"2019/08/26 06:19:15.011 -04:00", "2019/08/26 06:22:14.011 -04:00"}, levels: []pb.LogLevel{pb.LogLevel_Warn}, expect: []string{ + `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, `[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, `[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, }, }, @@ -398,6 +418,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { levels: []pb.LogLevel{pb.LogLevel_Error}, expect: []string{ `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, }, }, // 13 @@ -406,6 +427,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { levels: []pb.LogLevel{pb.LogLevel_Info}, patterns: []string{".*partern.*"}, expect: []string{ + `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, `[2019/08/26 06:23:14.011 -04:00] [INFO] [printer.go:41] ["partern test to TiDB."]`, `[2019/08/27 06:23:14.011 -04:00] [INFO] [printer.go:41] ["partern test txn to TiDB."]`, }, From f53e8a872d48e2c74c7d78037803ce64140879f7 Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Mon, 6 Jul 2020 13:51:08 +0800 Subject: [PATCH 05/19] update CI job name --- .github/workflows/test.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/test.yaml b/.github/workflows/test.yaml index 1293e67..0591fb9 100644 --- a/.github/workflows/test.yaml +++ b/.github/workflows/test.yaml @@ -6,7 +6,7 @@ on: - master jobs: - release_packages: + test: runs-on: ubuntu-latest steps: - uses: actions/checkout@v1 From b08939af26c651ad6a56380ab99b3a9ea66e7b74 Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Mon, 6 Jul 2020 14:11:11 +0800 Subject: [PATCH 06/19] update comment --- search_log.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/search_log.go b/search_log.go index 738f68a..71fef7a 100644 --- a/search_log.go +++ b/search_log.go @@ -176,7 +176,7 @@ func readLine(reader *bufio.Reader) (string, error) { } // Read a line from the end of a file. -// TODO: byte by byte read is low effiency, we can improve it +// TODO: read byte by byte is low efficiency, we can improve it, for example, read 1024 bytes one time func readLineReverse(file *os.File, endCursor int64) string { var line []byte var cursor = endCursor From f386b970799345fd56c004d4aa067273f3997e98 Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Mon, 6 Jul 2020 22:33:48 +0800 Subject: [PATCH 07/19] keep invalid log time and level same as previous one --- search_log.go | 10 +++++----- search_log_test.go | 33 +++++++++++++-------------------- 2 files changed, 18 insertions(+), 25 deletions(-) diff --git a/search_log.go b/search_log.go index 71fef7a..c0e07d1 100644 --- a/search_log.go +++ b/search_log.go @@ -285,7 +285,7 @@ type logIterator struct { fileIndex int reader *bufio.Reader pending []*os.File - preTime int64 + preLog *pb.LogMessage } // The Close method close all resources the iterator has. @@ -322,18 +322,18 @@ nextLine: } item, err := parseLogItem(line) if err != nil { - if iter.preTime == 0 { + if iter.preLog == nil { continue } // handle invalid log // make whole line as log message with pre time and unknown log_level item = &pb.LogMessage{ - Time: iter.preTime, - Level: pb.LogLevel_UNKNOWN, + Time: iter.preLog.Time, + Level: iter.preLog.Level, Message: line, } } else { - iter.preTime = item.Time + iter.preLog = item } if item.Time > iter.end { return nil, io.EOF diff --git a/search_log_test.go b/search_log_test.go index 5a2860f..3295504 100644 --- a/search_log_test.go +++ b/search_log_test.go @@ -260,13 +260,13 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, + `[2019/08/26 06:19:16.011 -04:00] [DEBUG] This is an invalid log blablabla`, `[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:20:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, + `[2019/08/26 06:22:14.011 -04:00] [INFO] This is also an invalid log contains partern ...`, `[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, @@ -281,13 +281,13 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, + `[2019/08/26 06:19:16.011 -04:00] [DEBUG] This is an invalid log blablabla`, `[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:20:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, + `[2019/08/26 06:22:14.011 -04:00] [INFO] This is also an invalid log contains partern ...`, `[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, @@ -304,7 +304,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, + `[2019/08/26 06:19:16.011 -04:00] [DEBUG] This is an invalid log blablabla`, `[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`, }, }, @@ -316,7 +316,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, + `[2019/08/26 06:22:14.011 -04:00] [INFO] This is also an invalid log contains partern ...`, `[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, @@ -331,13 +331,13 @@ func (s *searchLogSuite) TestLogIterator(c *C) { expect: []string{ `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, + `[2019/08/26 06:19:16.011 -04:00] [DEBUG] This is an invalid log blablabla`, `[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:20:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, + `[2019/08/26 06:22:14.011 -04:00] [INFO] This is also an invalid log contains partern ...`, `[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, }, }, @@ -356,7 +356,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, + `[2019/08/26 06:19:16.011 -04:00] [DEBUG] This is an invalid log blablabla`, }, }, // 7 @@ -366,7 +366,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { `[2019/08/26 06:19:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, + `[2019/08/26 06:19:16.011 -04:00] [DEBUG] This is an invalid log blablabla`, }, }, // 8 @@ -375,8 +375,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { levels: []pb.LogLevel{pb.LogLevel_Debug}, expect: []string{ `[2019/08/26 06:19:16.011 -04:00] [DEBUG] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, - `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, + `[2019/08/26 06:19:16.011 -04:00] [DEBUG] This is an invalid log blablabla`, }, }, // 9 @@ -384,9 +383,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { search: timeRange{"2019/08/26 06:19:15.011 -04:00", "2019/08/26 06:22:14.011 -04:00"}, levels: []pb.LogLevel{pb.LogLevel_Trace}, expect: []string{ - `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, `[2019/08/26 06:19:17.011 -04:00] [TRACE] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, }, }, // 10 @@ -394,11 +391,10 @@ func (s *searchLogSuite) TestLogIterator(c *C) { search: timeRange{"2019/08/26 06:19:15.011 -04:00", "2019/08/26 06:22:14.011 -04:00"}, levels: []pb.LogLevel{pb.LogLevel_Info}, expect: []string{ - `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, `[2019/08/26 06:20:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:21:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, + `[2019/08/26 06:22:14.011 -04:00] [INFO] This is also an invalid log contains partern ...`, }, }, // 11 @@ -406,9 +402,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { search: timeRange{"2019/08/26 06:19:15.011 -04:00", "2019/08/26 06:22:14.011 -04:00"}, levels: []pb.LogLevel{pb.LogLevel_Warn}, expect: []string{ - `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, `[2019/08/26 06:21:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, `[2019/08/26 06:22:14.011 -04:00] [WARN] [printer.go:41] ["Welcome to TiDB."]`, }, }, @@ -418,7 +412,6 @@ func (s *searchLogSuite) TestLogIterator(c *C) { levels: []pb.LogLevel{pb.LogLevel_Error}, expect: []string{ `[2019/08/26 06:19:15.011 -04:00] [ERROR] [printer.go:41] ["Welcome to TiDB."]`, - `[2019/08/26 06:19:16.011 -04:00] [UNKNOWN] This is an invalid log blablabla`, }, }, // 13 @@ -427,7 +420,7 @@ func (s *searchLogSuite) TestLogIterator(c *C) { levels: []pb.LogLevel{pb.LogLevel_Info}, patterns: []string{".*partern.*"}, expect: []string{ - `[2019/08/26 06:22:14.011 -04:00] [UNKNOWN] This is also an invalid log contains partern ...`, + `[2019/08/26 06:22:14.011 -04:00] [INFO] This is also an invalid log contains partern ...`, `[2019/08/26 06:23:14.011 -04:00] [INFO] [printer.go:41] ["partern test to TiDB."]`, `[2019/08/27 06:23:14.011 -04:00] [INFO] [printer.go:41] ["partern test txn to TiDB."]`, }, From b5ead576cfe477c2423165b404a7331bc03b5c92 Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Tue, 7 Jul 2020 09:18:16 +0800 Subject: [PATCH 08/19] set max lines to read for get valid log to 10 --- search_log.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/search_log.go b/search_log.go index c0e07d1..389128e 100644 --- a/search_log.go +++ b/search_log.go @@ -74,13 +74,13 @@ func resolveFiles(logFilePath string, beginTime, endTime int64) ([]logFile, erro } reader := bufio.NewReader(file) - firstItem, err := readFirstValidLog(reader, 0) + firstItem, err := readFirstValidLog(reader, 10) if err != nil { skipFiles = append(skipFiles, file) return nil } - lastItem, err := readLastValidLog(file, 0) + lastItem, err := readLastValidLog(file, 10) if err != nil { skipFiles = append(skipFiles, file) return nil From 2f47a32186a173b4b7b069efd1ba46c8226fd229 Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Tue, 7 Jul 2020 11:02:17 +0800 Subject: [PATCH 09/19] test read and append log file --- export_test.go | 9 +++-- search_log.go | 10 +++-- search_log_test.go | 99 ++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 111 insertions(+), 7 deletions(-) diff --git a/export_test.go b/export_test.go index b5a4443..4fbe786 100644 --- a/export_test.go +++ b/export_test.go @@ -15,8 +15,9 @@ package sysutil // Export some function to for test purpose var ( - ParseLogItem = parseLogItem - ReadLine = readLine - ParseTimeStamp = parseTimeStamp - ResolveFiles = resolveFiles + ParseLogItem = parseLogItem + ReadLine = readLine + ReadLineReverse = readLineReverse + ParseTimeStamp = parseTimeStamp + ResolveFiles = resolveFiles ) diff --git a/search_log.go b/search_log.go index 389128e..0ef497b 100644 --- a/search_log.go +++ b/search_log.go @@ -182,7 +182,14 @@ func readLineReverse(file *os.File, endCursor int64) string { var cursor = endCursor stat, _ := file.Stat() filesize := stat.Size() + fmt.Println("current filesize:", filesize) for { + // stop if we are at the begining + // check it in the start to avoid read beyond the size + if cursor <= -filesize { + break + } + cursor-- file.Seek(cursor, io.SeekEnd) @@ -194,9 +201,6 @@ func readLineReverse(file *os.File, endCursor int64) string { break } line = append(line, char[0]) - if cursor == -filesize { // stop if we are at the begining - break - } } for i, j := 0, len(line)-1; i < j; i, j = i+1, j-1 { line[i], line[j] = line[j], line[i] diff --git a/search_log_test.go b/search_log_test.go index 3295504..41b2476 100644 --- a/search_log_test.go +++ b/search_log_test.go @@ -534,3 +534,102 @@ func (s *searchLogSuite) TestParseLogItem(c *C) { c.Assert(item.Message, Equals, cas.message) } } + +func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) { + // step 1. initial a log file + s.writeTmpFile(c, "tidb.log", []string{ + `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", + }) + + // step 2. open it as read only mode + path := filepath.Join(s.tmpDir, "tidb.log") + fmt.Println("path: ", path) + file, err := os.OpenFile(path, os.O_RDONLY, os.ModePerm) + c.Assert(err, IsNil, Commentf("open file %s failed", path)) + defer file.Close() + + stat, _ := file.Stat() + filesize := stat.Size() + fmt.Println("initial filesize: ", filesize) + + // step 3. run a goroutine to append some new logs to the file + go func() { + file_append, err := os.OpenFile(path, os.O_APPEND|os.O_WRONLY, os.ModeAppend) + c.Assert(err, IsNil, Commentf("open file as append mode %s failed", path)) + defer file_append.Close() + + for i := 40; i < 45; i++ { + line := fmt.Sprintf("[2020/07/07 06:%d:17.011 -04:00] [INFO] appended logs\n", i) + _, err := file_append.WriteString(line) + c.Assert(err, IsNil, Commentf("write %s failed", line)) + fmt.Print("write line: ", line) + + time.Sleep(50 * time.Millisecond) + } + }() + + // step 4. keep calling readLineReverse util it is empty + var endCursor int64 + for { + line := sysutil.ReadLineReverse(file, endCursor) + fmt.Print("read line: ", line) + // read out the file + if len(line) == 0 { + break + } + endCursor -= int64(len(line)) + + time.Sleep(60 * time.Millisecond) + } + + // print final content + file.Seek(0, io.SeekStart) + var content = make([]byte, 1024) + file.Read(content) + fmt.Println("final content:\n", string(content)) +} + +// result: (may be different every time) +// path: /var/folders/8z/_463bq6100qgyt1ns0zsf3x00000gn/T/sysutil584451097/tidb.log +// initial filesize: 385 +// current filesize: 385 +// write line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs +// read line: [2020/07/07 0FO] [printer.go:41] ["Welcome to TiDB."] +// write line: [2020/07/07 06:41:17.011 -04:00] [INFO] appended logs +// current filesize: 493 +// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs +// write line: [2020/07/07 06:42:17.011 -04:00] [INFO] appended logs +// current filesize: 547 +// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs +// write line: [2020/07/07 06:43:17.011 -04:00] [INFO] appended logs +// current filesize: 601 +// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs +// write line: [2020/07/07 06:44:17.011 -04:00] [INFO] appended logs +// current filesize: 655 +// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs +// current filesize: 655 +// read line: [2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] +// current filesize: 655 +// read line: [2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] +// current filesize: 655 +// read line: [2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] +// current filesize: 655 +// read line: [2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] +// current filesize: 655 +// read line: [2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] +// current filesize: 655 +// read line: final content: +// [2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] +// [2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] +// [2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] +// [2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] +// [2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] +// [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs +// [2020/07/07 06:41:17.011 -04:00] [INFO] appended logs +// [2020/07/07 06:42:17.011 -04:00] [INFO] appended logs +// [2020/07/07 06:43:17.011 -04:00] [INFO] appended logs +// [2020/07/07 06:44:17.011 -04:00] [INFO] appended logs From b935fdb1a4b47de65d19db7f215b653a2a1a16d8 Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Tue, 7 Jul 2020 13:51:00 +0800 Subject: [PATCH 10/19] fix readLineReverse to avoid race - read from file io.SeekEnd will read incorrect content when other threads append logs --- search_log.go | 20 +++++++------- search_log_test.go | 65 +++++++++------------------------------------- 2 files changed, 21 insertions(+), 64 deletions(-) diff --git a/search_log.go b/search_log.go index 0ef497b..6aeb824 100644 --- a/search_log.go +++ b/search_log.go @@ -140,7 +140,8 @@ func readFirstValidLog(reader *bufio.Reader, tryLines int64) (*pb.LogMessage, er // parameter tryLines: if value is 0, means unlimited func readLastValidLog(file *os.File, tryLines int64) (*pb.LogMessage, error) { var tried int64 - var endCursor int64 + stat, _ := file.Stat() + endCursor := stat.Size() for { line := readLineReverse(file, endCursor) // read out the file @@ -175,29 +176,26 @@ func readLine(reader *bufio.Reader) (string, error) { return string(line), nil } -// Read a line from the end of a file. +// Read a line from the end of a file +// startCursor initial value should be the filesize // TODO: read byte by byte is low efficiency, we can improve it, for example, read 1024 bytes one time -func readLineReverse(file *os.File, endCursor int64) string { +func readLineReverse(file *os.File, startCursor int64) string { var line []byte - var cursor = endCursor - stat, _ := file.Stat() - filesize := stat.Size() - fmt.Println("current filesize:", filesize) + var cursor = startCursor for { // stop if we are at the begining // check it in the start to avoid read beyond the size - if cursor <= -filesize { + if cursor <= 0 { break } cursor-- - file.Seek(cursor, io.SeekEnd) - + file.Seek(cursor, io.SeekStart) char := make([]byte, 1) file.Read(char) // stop if we find a line - if cursor != endCursor-1 && (char[0] == 10 || char[0] == 13) { + if cursor != startCursor-1 && (char[0] == 10 || char[0] == 13) { break } line = append(line, char[0]) diff --git a/search_log_test.go b/search_log_test.go index 41b2476..ba3b4d0 100644 --- a/search_log_test.go +++ b/search_log_test.go @@ -547,14 +547,12 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) { // step 2. open it as read only mode path := filepath.Join(s.tmpDir, "tidb.log") - fmt.Println("path: ", path) file, err := os.OpenFile(path, os.O_RDONLY, os.ModePerm) c.Assert(err, IsNil, Commentf("open file %s failed", path)) defer file.Close() stat, _ := file.Stat() filesize := stat.Size() - fmt.Println("initial filesize: ", filesize) // step 3. run a goroutine to append some new logs to the file go func() { @@ -566,70 +564,31 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) { line := fmt.Sprintf("[2020/07/07 06:%d:17.011 -04:00] [INFO] appended logs\n", i) _, err := file_append.WriteString(line) c.Assert(err, IsNil, Commentf("write %s failed", line)) - fmt.Print("write line: ", line) time.Sleep(50 * time.Millisecond) } }() - // step 4. keep calling readLineReverse util it is empty - var endCursor int64 + // step 4. keep calling readLineReverse until it is empty + expected := []string{ + `[2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", + `[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", + `[2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", + `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", + `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", + } + i := 0 + endCursor := filesize for { line := sysutil.ReadLineReverse(file, endCursor) - fmt.Print("read line: ", line) // read out the file if len(line) == 0 { break } + c.Assert(line, Equals, expected[i], Commentf("expected: %v, got: %v", expected[i], line)) + i++ endCursor -= int64(len(line)) time.Sleep(60 * time.Millisecond) } - - // print final content - file.Seek(0, io.SeekStart) - var content = make([]byte, 1024) - file.Read(content) - fmt.Println("final content:\n", string(content)) } - -// result: (may be different every time) -// path: /var/folders/8z/_463bq6100qgyt1ns0zsf3x00000gn/T/sysutil584451097/tidb.log -// initial filesize: 385 -// current filesize: 385 -// write line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs -// read line: [2020/07/07 0FO] [printer.go:41] ["Welcome to TiDB."] -// write line: [2020/07/07 06:41:17.011 -04:00] [INFO] appended logs -// current filesize: 493 -// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs -// write line: [2020/07/07 06:42:17.011 -04:00] [INFO] appended logs -// current filesize: 547 -// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs -// write line: [2020/07/07 06:43:17.011 -04:00] [INFO] appended logs -// current filesize: 601 -// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs -// write line: [2020/07/07 06:44:17.011 -04:00] [INFO] appended logs -// current filesize: 655 -// read line: [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs -// current filesize: 655 -// read line: [2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] -// current filesize: 655 -// read line: [2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] -// current filesize: 655 -// read line: [2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] -// current filesize: 655 -// read line: [2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] -// current filesize: 655 -// read line: [2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] -// current filesize: 655 -// read line: final content: -// [2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] -// [2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] -// [2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] -// [2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] -// [2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."] -// [2020/07/07 06:40:17.011 -04:00] [INFO] appended logs -// [2020/07/07 06:41:17.011 -04:00] [INFO] appended logs -// [2020/07/07 06:42:17.011 -04:00] [INFO] appended logs -// [2020/07/07 06:43:17.011 -04:00] [INFO] appended logs -// [2020/07/07 06:44:17.011 -04:00] [INFO] appended logs From f43ae9342653346a5f11558c14bef98b4a8af264 Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Tue, 7 Jul 2020 15:23:25 +0800 Subject: [PATCH 11/19] improve performance for reading content from the end of log file - read 512 bytes once instead of just 1 byte --- export_test.go | 10 +++---- search_log.go | 65 ++++++++++++++++++++++++++-------------------- search_log_test.go | 14 +++++----- 3 files changed, 49 insertions(+), 40 deletions(-) diff --git a/export_test.go b/export_test.go index 4fbe786..28a368a 100644 --- a/export_test.go +++ b/export_test.go @@ -15,9 +15,9 @@ package sysutil // Export some function to for test purpose var ( - ParseLogItem = parseLogItem - ReadLine = readLine - ReadLineReverse = readLineReverse - ParseTimeStamp = parseTimeStamp - ResolveFiles = resolveFiles + ParseLogItem = parseLogItem + ReadLine = readLine + ReadLastLines = readLastLines + ParseTimeStamp = parseTimeStamp + ResolveFiles = resolveFiles ) diff --git a/search_log.go b/search_log.go index 6aeb824..1b4b361 100644 --- a/search_log.go +++ b/search_log.go @@ -117,7 +117,6 @@ func resolveFiles(logFilePath string, beginTime, endTime int64) ([]logFile, erro return logFiles, err } -// parameter tryLines: if value is 0, means unlimited func readFirstValidLog(reader *bufio.Reader, tryLines int64) (*pb.LogMessage, error) { var tried int64 for { @@ -130,31 +129,33 @@ func readFirstValidLog(reader *bufio.Reader, tryLines int64) (*pb.LogMessage, er return item, nil } tried++ - if tryLines > 0 && tried >= tryLines { + if tried >= tryLines { break } } return nil, errors.New("not a valid log file") } -// parameter tryLines: if value is 0, means unlimited -func readLastValidLog(file *os.File, tryLines int64) (*pb.LogMessage, error) { - var tried int64 +func readLastValidLog(file *os.File, tryLines int) (*pb.LogMessage, error) { + var tried int stat, _ := file.Stat() endCursor := stat.Size() for { - line := readLineReverse(file, endCursor) + lines := readLastLines(file, endCursor) // read out the file - if len(line) == 0 { + if len(lines) == 0 { break } - endCursor -= int64(len(line)) - item, err := parseLogItem(line) - if err == nil { - return item, nil + endCursor -= int64(len(lines)) + linesSlice := strings.FieldsFunc(lines, func(c rune) bool { return c == '\n' || c == '\r' }) + for i := len(linesSlice) - 1; i >= 0; i-- { + item, err := parseLogItem(linesSlice[i]) + if err == nil { + return item, nil + } } - tried++ - if tryLines > 0 && tried >= tryLines { + tried += len(linesSlice) + if tried >= tryLines { break } } @@ -176,11 +177,10 @@ func readLine(reader *bufio.Reader) (string, error) { return string(line), nil } -// Read a line from the end of a file +// Read lines from the end of a file // startCursor initial value should be the filesize -// TODO: read byte by byte is low efficiency, we can improve it, for example, read 1024 bytes one time -func readLineReverse(file *os.File, startCursor int64) string { - var line []byte +func readLastLines(file *os.File, startCursor int64) string { + var lines []byte var cursor = startCursor for { // stop if we are at the begining @@ -189,21 +189,30 @@ func readLineReverse(file *os.File, startCursor int64) string { break } - cursor-- + var size int64 = 512 + if cursor < size { + size = cursor + } + cursor -= size + file.Seek(cursor, io.SeekStart) - char := make([]byte, 1) - file.Read(char) + chars := make([]byte, size) + file.Read(chars) + lines = append(chars, lines...) - // stop if we find a line - if cursor != startCursor-1 && (char[0] == 10 || char[0] == 13) { - break + // find first '\n' or '\r' + for i := 0; i < len(chars); i++ { + // reach the line end + if i >= len(lines)-1 { + break + } + + if (chars[i] == 10 || chars[i] == 13) && chars[i+1] != 10 && chars[i+1] != 13 { + return string(lines[i+1:]) + } } - line = append(line, char[0]) - } - for i, j := 0, len(line)-1; i < j; i, j = i+1, j-1 { - line[i], line[j] = line[j], line[i] } - return string(line) + return string(lines) } // ParseLogLevel returns LogLevel from string and return LogLevel_Info if diff --git a/search_log_test.go b/search_log_test.go index ba3b4d0..a4e4d35 100644 --- a/search_log_test.go +++ b/search_log_test.go @@ -565,22 +565,22 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) { _, err := file_append.WriteString(line) c.Assert(err, IsNil, Commentf("write %s failed", line)) - time.Sleep(50 * time.Millisecond) + time.Sleep(10 * time.Millisecond) } }() // step 4. keep calling readLineReverse until it is empty expected := []string{ - `[2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", - `[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", - `[2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", - `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", + `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n" + + `[2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n" + + `[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n" + + `[2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", } i := 0 endCursor := filesize for { - line := sysutil.ReadLineReverse(file, endCursor) + line := sysutil.ReadLastLines(file, endCursor) // read out the file if len(line) == 0 { break @@ -589,6 +589,6 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) { i++ endCursor -= int64(len(line)) - time.Sleep(60 * time.Millisecond) + time.Sleep(15 * time.Millisecond) } } From b3464a12b75a69d48aede72c9d0aaa18ceaf31d1 Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Tue, 7 Jul 2020 15:34:56 +0800 Subject: [PATCH 12/19] refine --- search_log.go | 6 +++--- search_log_test.go | 6 +++--- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/search_log.go b/search_log.go index 1b4b361..8649427 100644 --- a/search_log.go +++ b/search_log.go @@ -178,10 +178,10 @@ func readLine(reader *bufio.Reader) (string, error) { } // Read lines from the end of a file -// startCursor initial value should be the filesize -func readLastLines(file *os.File, startCursor int64) string { +// endCursor initial value should be the filesize +func readLastLines(file *os.File, endCursor int64) string { var lines []byte - var cursor = startCursor + var cursor = endCursor for { // stop if we are at the begining // check it in the start to avoid read beyond the size diff --git a/search_log_test.go b/search_log_test.go index a4e4d35..b1d88ce 100644 --- a/search_log_test.go +++ b/search_log_test.go @@ -538,7 +538,7 @@ func (s *searchLogSuite) TestParseLogItem(c *C) { func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) { // step 1. initial a log file s.writeTmpFile(c, "tidb.log", []string{ - `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:13.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, `[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, @@ -569,13 +569,13 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) { } }() - // step 4. keep calling readLineReverse until it is empty + // step 4. keep calling ReadLastLines until reach the beginning expected := []string{ `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n" + `[2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n" + `[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n" + `[2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", - `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", + `[2019/08/26 06:22:13.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]` + "\n", } i := 0 endCursor := filesize From 650740ff2011b947c457799647c429de3d8d53b9 Mon Sep 17 00:00:00 2001 From: Sparkle <1284531+baurine@users.noreply.github.com> Date: Wed, 8 Jul 2020 11:39:50 +0800 Subject: [PATCH 13/19] Update search_log.go Co-authored-by: Wenxuan <hi@breeswish.org> --- search_log.go | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/search_log.go b/search_log.go index 8649427..5cb0573 100644 --- a/search_log.go +++ b/search_log.go @@ -191,9 +191,10 @@ func readLastLines(file *os.File, endCursor int64) string { var size int64 = 512 if cursor < size { - size = cursor + cursor = 0 + } else { + cursor -= size } - cursor -= size file.Seek(cursor, io.SeekStart) chars := make([]byte, size) From f628718daf0ec3d7dcf6582ca926544de6e8584d Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Wed, 8 Jul 2020 12:53:18 +0800 Subject: [PATCH 14/19] Revert "Update search_log.go" This reverts commit 650740ff2011b947c457799647c429de3d8d53b9. --- search_log.go | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/search_log.go b/search_log.go index 5cb0573..8649427 100644 --- a/search_log.go +++ b/search_log.go @@ -191,10 +191,9 @@ func readLastLines(file *os.File, endCursor int64) string { var size int64 = 512 if cursor < size { - cursor = 0 - } else { - cursor -= size + size = cursor } + cursor -= size file.Seek(cursor, io.SeekStart) chars := make([]byte, size) From 56008cfa4c27cfb4a69b06de9d718faab2edf81d Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Wed, 8 Jul 2020 13:32:59 +0800 Subject: [PATCH 15/19] add benchmark for readLastLines --- search_log_test.go | 34 ++++++++++++++++++++++++++++++++++ 1 file changed, 34 insertions(+) diff --git a/search_log_test.go b/search_log_test.go index b1d88ce..12a22d8 100644 --- a/search_log_test.go +++ b/search_log_test.go @@ -592,3 +592,37 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) { time.Sleep(15 * time.Millisecond) } } + +func (s *searchLogSuite) BenchmarkReadLastLines(c *C) { + // step 1. initial a log file + s.writeTmpFile(c, "tidb.log", []string{ + `[2019/08/26 06:22:13.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:14.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:15.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:16.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + `[2019/08/26 06:22:17.011 -04:00] [INFO] [printer.go:41] ["Welcome to TiDB."]`, + }) + + // step 2. open it as read only mode + path := filepath.Join(s.tmpDir, "tidb.log") + file, err := os.OpenFile(path, os.O_RDONLY, os.ModePerm) + c.Assert(err, IsNil, Commentf("open file %s failed", path)) + defer file.Close() + + stat, _ := file.Stat() + filesize := stat.Size() + + // step 3. start to benchmark + c.ResetTimer() + for i := 0; i < c.N; i++ { + sysutil.ReadLastLines(file, filesize) + } +} + +// run benchmark by `go test -check.b` +// result: +// searchLogSuite.BenchmarkReadLastLines 1000000 1920 ns/op +// searchLogSuite.BenchmarkReadLastLines 1000000 1892 ns/op +// result for the old readLastLine method: +// searchLogSuite.BenchmarkReadLastLine 10000 124423 ns/op +// searchLogSuite.BenchmarkReadLastLine 10000 126135 ns/op From 6921c86d26194dc0cfbe870041aa71bfcb7492f3 Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Wed, 8 Jul 2020 15:08:32 +0800 Subject: [PATCH 16/19] make readLastLines return slice instead of string --- search_log.go | 27 ++++++++++++++++----------- search_log_test.go | 12 ++++++------ 2 files changed, 22 insertions(+), 17 deletions(-) diff --git a/search_log.go b/search_log.go index 8649427..a903525 100644 --- a/search_log.go +++ b/search_log.go @@ -141,20 +141,19 @@ func readLastValidLog(file *os.File, tryLines int) (*pb.LogMessage, error) { stat, _ := file.Stat() endCursor := stat.Size() for { - lines := readLastLines(file, endCursor) + lines, readBytes := readLastLines(file, endCursor) // read out the file - if len(lines) == 0 { + if readBytes == 0 { break } - endCursor -= int64(len(lines)) - linesSlice := strings.FieldsFunc(lines, func(c rune) bool { return c == '\n' || c == '\r' }) - for i := len(linesSlice) - 1; i >= 0; i-- { - item, err := parseLogItem(linesSlice[i]) + endCursor -= int64(readBytes) + for i := len(lines) - 1; i >= 0; i-- { + item, err := parseLogItem(lines[i]) if err == nil { return item, nil } } - tried += len(linesSlice) + tried += len(lines) if tried >= tryLines { break } @@ -179,8 +178,9 @@ func readLine(reader *bufio.Reader) (string, error) { // Read lines from the end of a file // endCursor initial value should be the filesize -func readLastLines(file *os.File, endCursor int64) string { +func readLastLines(file *os.File, endCursor int64) ([]string, int) { var lines []byte + var firstNonNewlinePos int var cursor = endCursor for { // stop if we are at the begining @@ -203,16 +203,21 @@ func readLastLines(file *os.File, endCursor int64) string { // find first '\n' or '\r' for i := 0; i < len(chars); i++ { // reach the line end + // the first newline may be in the line end at the first round if i >= len(lines)-1 { break } - if (chars[i] == 10 || chars[i] == 13) && chars[i+1] != 10 && chars[i+1] != 13 { - return string(lines[i+1:]) + firstNonNewlinePos = i + 1 + break } } + if firstNonNewlinePos > 0 { + break + } } - return string(lines) + finalStr := string(lines[firstNonNewlinePos:]) + return strings.Split(strings.ReplaceAll(finalStr, "\r\n", "\n"), "\n"), len(finalStr) } // ParseLogLevel returns LogLevel from string and return LogLevel_Info if diff --git a/search_log_test.go b/search_log_test.go index 12a22d8..5aeb280 100644 --- a/search_log_test.go +++ b/search_log_test.go @@ -580,14 +580,14 @@ func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) { i := 0 endCursor := filesize for { - line := sysutil.ReadLastLines(file, endCursor) + lines, readBytes := sysutil.ReadLastLines(file, endCursor) // read out the file - if len(line) == 0 { + if readBytes == 0 { break } - c.Assert(line, Equals, expected[i], Commentf("expected: %v, got: %v", expected[i], line)) + c.Assert(strings.Join(lines, "\n"), Equals, expected[i], Commentf("expected: %v, got: %v", expected[i], lines)) i++ - endCursor -= int64(len(line)) + endCursor -= int64(readBytes) time.Sleep(15 * time.Millisecond) } @@ -621,8 +621,8 @@ func (s *searchLogSuite) BenchmarkReadLastLines(c *C) { // run benchmark by `go test -check.b` // result: -// searchLogSuite.BenchmarkReadLastLines 1000000 1920 ns/op -// searchLogSuite.BenchmarkReadLastLines 1000000 1892 ns/op +// searchLogSuite.BenchmarkReadLastLines 1000000 2008 ns/op +// searchLogSuite.BenchmarkReadLastLines 1000000 2193 ns/op // result for the old readLastLine method: // searchLogSuite.BenchmarkReadLastLine 10000 124423 ns/op // searchLogSuite.BenchmarkReadLastLine 10000 126135 ns/op From 35d98d71b552b2abaf66b8f957de77a3cfe8a06f Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Wed, 8 Jul 2020 15:31:48 +0800 Subject: [PATCH 17/19] update comment --- search_log_test.go | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/search_log_test.go b/search_log_test.go index 5aeb280..5e067fc 100644 --- a/search_log_test.go +++ b/search_log_test.go @@ -623,6 +623,9 @@ func (s *searchLogSuite) BenchmarkReadLastLines(c *C) { // result: // searchLogSuite.BenchmarkReadLastLines 1000000 2008 ns/op // searchLogSuite.BenchmarkReadLastLines 1000000 2193 ns/op -// result for the old readLastLine method: +// result for the old readLastLine method when last line is 76 bytes long: // searchLogSuite.BenchmarkReadLastLine 10000 124423 ns/op // searchLogSuite.BenchmarkReadLastLine 10000 126135 ns/op +// result for the old readLastLine method when last line is 76*2 bytes long: +// searchLogSuite.BenchmarkReadLastLine 10000 247836 ns/op +// searchLogSuite.BenchmarkReadLastLine 10000 251958 ns/op From 82bb8b1e547f82996d9a30431ca9834c757bd0a3 Mon Sep 17 00:00:00 2001 From: Sparkle <1284531+baurine@users.noreply.github.com> Date: Thu, 9 Jul 2020 16:15:41 +0800 Subject: [PATCH 18/19] Update search_log.go Co-authored-by: Wenxuan <hi@breeswish.org> --- search_log.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/search_log.go b/search_log.go index a903525..b018ed5 100644 --- a/search_log.go +++ b/search_log.go @@ -342,7 +342,7 @@ nextLine: continue } // handle invalid log - // make whole line as log message with pre time and unknown log_level + // make whole line as log message with pre time and pre log_level item = &pb.LogMessage{ Time: iter.preLog.Time, Level: iter.preLog.Level, From f25244b6a32de1bdb28edc73297519d635368c8b Mon Sep 17 00:00:00 2001 From: baurine <2008.hbl@gmail.com> Date: Thu, 9 Jul 2020 21:17:00 +0800 Subject: [PATCH 19/19] slightly refine --- search_log.go | 13 ++++++------- 1 file changed, 6 insertions(+), 7 deletions(-) diff --git a/search_log.go b/search_log.go index b018ed5..3ed9a2e 100644 --- a/search_log.go +++ b/search_log.go @@ -271,22 +271,21 @@ func parseLogItem(s string) (*pb.LogMessage, error) { return item, nil } -const TimeStampLayout = "2006/01/02 15:04:05.000 -07:00" +const ( + timeStampLayout = "2006/01/02 15:04:05.000 -07:00" + timeStampLayoutLen = len(timeStampLayout) +) // TiDB / TiKV / PD unified log format // [2019/03/04 17:04:24.614 +08:00] ... func parseTimeStamp(s string) (int64, error) { - t, err := time.Parse(TimeStampLayout, s) + t, err := time.Parse(timeStampLayout, s) if err != nil { return 0, err } return t.UnixNano() / int64(time.Millisecond), nil } -// Only enable seek when position range is more than SEEK_THRESHOLD. -// The suggested value of SEEK_THRESHOLD is the biggest log size. -const SEEK_THRESHOLD = 1024 * 1024 - // logIterator implements Iterator and IteratorWithPeek interface. // It's used for reading logs from log files one by one by their // time. @@ -333,7 +332,7 @@ nextLine: continue } line = strings.TrimSpace(line) - if len(line) == 0 { + if iter.preLog == nil && len(line) < timeStampLayoutLen { continue } item, err := parseLogItem(line)