Support handle invalid logs #19

baurine · 2020-07-03T15:45:38Z

close #17 , close #16

What did:

Support handle the log files that include invalid logs in the beginning and end, try at most 10 lines to get the first valid log.
Support handle the log files that include invalid logs in the middle, treat the invalid log with previous log time, level, and message by the whole line content.
Fix the bug that would read incorrect content from the end of the log file when others append new contents to the file
Improve the performance for reading content from the end of the log file, read 512 bytes once instead of 1 byte

…legal-logs

baurine · 2020-07-06T06:22:04Z

@breeswish @crazycs520 @lonng PTAL, thanks!

baurine · 2020-07-06T06:25:47Z

search_log.go

@@ -136,20 +175,22 @@ 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.
+// TODO: read byte by byte is low efficiency, we can improve it, for example, read 1024 bytes one time


Can we refine by this way? (not sure whether it has some pitfalls.)

Sure, we can add a todo here.

baurine · 2020-07-06T06:32:27Z

search_log.go

 	stat, _ := file.Stat()
 	filesize := stat.Size()
 	for {
-		cursor -= 1
+		cursor--
 		file.Seek(cursor, io.SeekEnd)


What if the log has appended some new logs after the file is opened when calling file.seek(0, io.SeekEnd), does it work same as file.seek(filesize, io.SeekStart)?

Nice catch, I think we should add some tests for these scenarios.

ok, I will do some tests to check it.

Hi @lonng , add a test method TestReadAndAppendLogFile to test this case, it seems we will read the unexcepted result from the end when new contents is appending to the file. But we can try to resolve it in another PR.

will continue to fix it in this PR.

Fixed it by file.Seek(cursor, io.SeekStart).

breezewish · 2020-07-06T09:05:52Z

Support handle the log files that include invalid logs in the beginning and end, skip them until find a valid log.

Maybe we can set a threshold for this behaviour, i.e. maximum look ahead xxx bytes, in case of the whole big file is invalid logs and causing performance degrade

Support handle the log files that include invalid logs in the middle, treat the invalid log with previous log time, unknown log level, and message by the whole line content.

Maybe we can keep the same log time, log level as the previous one

baurine · 2020-07-06T09:40:22Z

Support handle the log files that include invalid logs in the beginning and end, skip them until find a valid log.

Maybe we can set a threshold for this behaviour, i.e. maximum look ahead xxx bytes, in case of the whole big file is invalid logs and causing performance degrade

There is a tryLines parameter to control the maximum lines to read, but currently tryLines is set to 0 to mean may read all lines, and no way to config it from outside. will make the default value to 10 lines, how about it?

Support handle the log files that include invalid logs in the middle, treat the invalid log with previous log time, unknown log level, and message by the whole line content.

Maybe we can keep the same log time, log level as the previous one

ok, and updated it.

baurine · 2020-07-07T03:58:31Z

search_log.go

 	stat, _ := file.Stat()
 	filesize := stat.Size()
+	fmt.Println("current filesize:", filesize)


Will remove it later

baurine · 2020-07-07T03:59:01Z

search_log_test.go

+	fmt.Println("final content:\n", string(content))
+}
+
+// result: (may be different every time)


Will remove later

crazycs520 · 2020-07-07T04:19:38Z

search_log_test.go

+
+	stat, _ := file.Stat()
+	filesize := stat.Size()
+	fmt.Println("initial filesize: ", filesize)


remove this?

crazycs520 · 2020-07-07T04:21:29Z

search_log_test.go

+			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)


crazycs520 · 2020-07-07T04:32:43Z

search_log_test.go

@@ -515,3 +534,102 @@ func (s *searchLogSuite) TestParseLogItem(c *C) {
 		c.Assert(item.Message, Equals, cas.message)
 	}
 }
+
+func (s *searchLogSuite) TestReadAndAppendLogFile(c *C) {


This test output is not expected. I think we need to re-implement the readLineReverse function.

Yep, I decided to continue to re-implement it in this PR.

- read from file io.SeekEnd will read incorrect content when other threads append logs

baurine · 2020-07-07T05:56:23Z

search_log.go


+		cursor--
+		file.Seek(cursor, io.SeekStart)


Replace file.Seek(cursor, io.SeekEnd) by file.Seek(cursor, io.SeekStart), the former way may read incorrect content from the end of a file when some others append new logs to this file.

- read 512 bytes once instead of just 1 byte

baurine · 2020-07-07T07:42:27Z

Addressed all comments, polished by the following work:

Fix the bug that would read incorrect content from the end of the log file when others append new contents to the file
Improve the performance for reading content from the end of the log file, read 512 bytes once instead of 1 byte

@breeswish @lonng @crazycs520 PTAL, thanks!

baurine · 2020-07-07T07:45:45Z

search_log.go

-		if cursor == -filesize { // stop if we are at the begining
-			break
+
+		var size int64 = 512


Read 512 bytes once instead of 1 byte.

I like this change very much, would you like to write a benchmark for this optimization?

Sure, let me try it.

Comparison:

Old way: searchLogSuite.BenchmarkReadLastLine 10000 124423 ns/op searchLogSuite.BenchmarkReadLastLine 10000 126135 ns/op New way: searchLogSuite.BenchmarkReadLastLines 1000000 1892 ns/op searchLogSuite.BenchmarkReadLastLines 1000000 1920 ns/op

Conclusion:

the new implementation is 65x (126135/1920) as fast as the old way. (the result should depend on the length of the last line. In this case, the last line is 76 bytes long. If we double the last line length, the old way cost time will be doubled too, see details in PR #20 )

breezewish · 2020-07-08T03:16:46Z

search_log.go

+			break
+		}
+		endCursor -= int64(len(lines))
+		linesSlice := strings.FieldsFunc(lines, func(c rune) bool { return c == '\n' || c == '\r' })


Maybe there will be problems when line ending is \r\n.

Yep, I thought that, let me try to polish it.

Polish it by strings.Split(strings.ReplaceAll(finalStr, "\r\n", "\n"), "\n") and put it inside the readLastLines method.

search_log.go

breezewish · 2020-07-08T03:18:59Z

search_log.go

+		cursor -= size
+
+		file.Seek(cursor, io.SeekStart)
+		chars := make([]byte, size)


We can move this line out of the loop and reuse the buffer to improve performance

Good idea! update it soon.

I tried but found it doesn't work well, including keep size value not change. Because file.Read(chars) reads len(chars) bytes content, so we need to make sure the chars is allocated by the size we need to read, instead of fixed 512 bytes.

breezewish · 2020-07-08T03:23:08Z

search_log.go

+		lines = append(chars, lines...)
+
+		// find first '\n' or '\r'
+		for i := 0; i < len(chars); i++ {


We only need to check \r and \n in the scanned bytes from this round, instead of previous rounds

Yes, it works as you said, len(chars) is the length of content just read in this round.

breezewish · 2020-07-08T03:23:41Z

Very cool!

crazycs520 · 2020-07-08T03:31:03Z

search_log.go

-	filesize := stat.Size()
+// Read lines from the end of a file
+// endCursor initial value should be the filesize
+func readLastLines(file *os.File, endCursor int64) string {


readLastLines look like maybe returns multiple lines, but the return parameter is string, should be []string?

I need to get read bytes by len(string) in its caller method, return []string will miss the length info, else I need to add an extra readSize return value. Which way is better?

I prefer to return lines []string, size int, it's more clear

Co-authored-by: Wenxuan <[email protected]>

This reverts commit 650740f.

search_log.go

breezewish

the rest LGTM. @crazycs520 PTAL

Co-authored-by: Wenxuan <[email protected]>

crazycs520

LGTM

baurine marked this pull request as draft July 3, 2020 15:45

support to handle invalid logs in the file beginning and end

dab3e40

baurine force-pushed the support-handle-illegal-logs branch from ba6e2e8 to dab3e40 Compare July 3, 2020 15:57

baurine added 4 commits July 6, 2020 11:15

support invalid log in the middle of log file

d2fbf9c

Merge remote-tracking branch 'upstream/master' into support-handle-il…

71a9f15

…legal-logs

refine

ca397ce

update test

e1084ad

baurine force-pushed the support-handle-illegal-logs branch from f82c3b0 to e1084ad Compare July 6, 2020 05:45

baurine added 2 commits July 6, 2020 13:51

update CI job name

f53e8a8

update comment

b08939a

baurine marked this pull request as ready for review July 6, 2020 06:19

baurine changed the title ~~[WIP] Support handle illegal logs~~ Support handle illegal logs Jul 6, 2020

baurine commented Jul 6, 2020

View reviewed changes

baurine changed the title ~~Support handle illegal logs~~ Support handle invalid logs Jul 6, 2020

baurine added 3 commits July 6, 2020 22:33

keep invalid log time and level same as previous one

f386b97

set max lines to read for get valid log to 10

b5ead57

test read and append log file

2f47a32

baurine commented Jul 7, 2020

View reviewed changes

crazycs520 reviewed Jul 7, 2020

View reviewed changes

fix readLineReverse to avoid race

b935fdb

- read from file io.SeekEnd will read incorrect content when other threads append logs

baurine commented Jul 7, 2020

View reviewed changes

baurine added 2 commits July 7, 2020 15:23

improve performance for reading content from the end of log file

f43ae93

- read 512 bytes once instead of just 1 byte

refine

b3464a1

baurine commented Jul 7, 2020

View reviewed changes

breezewish reviewed Jul 8, 2020

View reviewed changes

crazycs520 reviewed Jul 8, 2020

View reviewed changes

baurine and others added 2 commits July 8, 2020 11:39

Update search_log.go

650740f

Co-authored-by: Wenxuan <[email protected]>

Revert "Update search_log.go"

f628718

This reverts commit 650740f.

baurine mentioned this pull request Jul 8, 2020

add benchmark for readLastLine method #20

Closed

add benchmark for readLastLines

56008cf

baurine force-pushed the support-handle-illegal-logs branch from 508ad40 to 56008cf Compare July 8, 2020 06:06

baurine added 2 commits July 8, 2020 15:08

make readLastLines return slice instead of string

6921c86

update comment

35d98d7

breezewish reviewed Jul 9, 2020

View reviewed changes

search_log.go Outdated Show resolved Hide resolved

breezewish previously approved these changes Jul 9, 2020

View reviewed changes

Update search_log.go

82bb8b1

Co-authored-by: Wenxuan <[email protected]>

baurine dismissed breezewish’s stale review via 82bb8b1 July 9, 2020 08:15

slightly refine

f25244b

baurine mentioned this pull request Jul 9, 2020

*: support handle search invalid logs file tikv/tikv#8224

Merged

crazycs520 approved these changes Jul 10, 2020

View reviewed changes

crazycs520 merged commit 275df26 into pingcap:master Jul 10, 2020

baurine deleted the support-handle-illegal-logs branch July 10, 2020 09:34

This was referenced Jul 15, 2020

search logs: update sysutil to support search logs include invalid lines pingcap/tidb#18579

Merged

search logs: update sysutil to support search logs include invalid lines tikv/pd#2652

Merged

ti-srebot mentioned this pull request Jul 15, 2020

search logs: update sysutil to support search logs include invalid lines (#18579) pingcap/tidb#18610

Merged

ti-srebot mentioned this pull request Aug 19, 2020

*: support handle search invalid logs file (#8224) tikv/tikv#8464

Closed

Support handle invalid logs #19

Support handle invalid logs #19

Conversation

baurine commented Jul 3, 2020 • edited Loading

baurine commented Jul 6, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

baurine Jul 6, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

breezewish commented Jul 6, 2020

baurine commented Jul 6, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

baurine commented Jul 7, 2020

baurine Jul 7, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

baurine Jul 8, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

breezewish commented Jul 8, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

crazycs520 Jul 8, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

breezewish left a comment

Choose a reason for hiding this comment

crazycs520 left a comment

Choose a reason for hiding this comment

baurine commented Jul 3, 2020 •

edited

Loading

baurine Jul 6, 2020 •

edited

Loading

baurine commented Jul 6, 2020 •

edited

Loading

baurine Jul 7, 2020 •

edited

Loading

baurine Jul 8, 2020 •

edited

Loading

crazycs520 Jul 8, 2020 •

edited

Loading