从大文件查找记录,24核64G服务器上反而比i5 3470慢,懵

这个程序是从一个1.07G(315w条)的日志文件中查找指定类型的日志,并将指定类型的日志写到独立文件中 日志文件中每行一条json日志 日志样例,隐去了其余字段,实际一条约350字节 ```json 2016/08/18 11:48:19 {"date":"2016-08-18 11:48:19","log":"money","id":400} ``` 在普通公司电脑上跑出来数据i5 3470,8G,5400转硬盘 ```javascript D:\gotest\special_log>special_log.exe -t collection readall time: 1.8052026 total lines: 3151749 deceode time: 1.8062033 D:\gotest\special_log>special_log.exe -t collection readall time: 1.7971970000000002 total lines: 3151749 deceode time: 1.800198 D:\gotest\special_log>special_log.exe -t collection readall time: 1.81621 total lines: 3151749 deceode time: 1.81621 ``` 在服务器上 ```javascript [root@localhost logs]# ./special_log -f 20160831_log_logs.txt -t money readall time: 4.803762707 total lines: 3151749 deceode time: 4.803832504 total time 4.803855245 [root@localhost logs]# ./special_log -f 20160831_log_logs.txt -t money readall time: 4.689143216 total lines: 3151749 deceode time: 4.689217291 total time 4.689249867 [root@localhost logs]# ./special_log -f 20160831_log_logs.txt -t money readall time: 4.821515715 total lines: 3151749 deceode time: 4.821584778 total time 4.8216138090000005 ``` 服务器上反而更慢了,有点懵逼—_—! 尝试修改runtime.GOMAXPROCS和协程数,都没什么效果,运行时能看到所有cpu核都在工作 本地pprof ```javascript (pprof) top 10 3110ms of 4170ms total (74.58%) Dropped 60 nodes (cum <= 20.85ms) Showing top 10 nodes out of 76 (cum >= 3600ms) flat flat% sum% cum cum% 680ms 16.31% 16.31% 690ms 16.55% runtime.cgocall 510ms 12.23% 28.54% 860ms 20.62% bytes.Index 450ms 10.79% 39.33% 460ms 11.03% runtime.gopanic 420ms 10.07% 49.40% 420ms 10.07% runtime.memclr 340ms 8.15% 57.55% 340ms 8.15% unicode.init 260ms 6.24% 63.79% 260ms 6.24% runtime.duffcopy 190ms 4.56% 68.35% 530ms 12.71% bytes.init 100ms 2.40% 70.74% 800ms 19.18% runtime.mallocinit 80ms 1.92% 72.66% 570ms 13.67% runtime.chanrecv 80ms 1.92% 74.58% 3600ms 86.33% runtime.memmove ``` 服务器pprof ```javascript (pprof) top 10 17020ms of 24340ms total (69.93%) Dropped 104 nodes (cum <= 121.70ms) Showing top 10 nodes out of 79 (cum >= 1040ms) flat flat% sum% cum cum% 4470ms 18.36% 18.36% 4470ms 18.36% runtime.futex 2760ms 11.34% 29.70% 8280ms 34.02% runtime.lock 2040ms 8.38% 38.09% 2040ms 8.38% runtime/internal/atomic.Xchg 1760ms 7.23% 45.32% 1760ms 7.23% runtime.procyield 1620ms 6.66% 51.97% 3620ms 14.87% bytes.Index 1340ms 5.51% 57.48% 1340ms 5.51% runtime.indexbytebody 880ms 3.62% 61.09% 7350ms 30.20% runtime.findrunnable 750ms 3.08% 64.17% 750ms 3.08% runtime.osyield 710ms 2.92% 67.09% 710ms 2.92% runtime/internal/atomic.Xadd 690ms 2.83% 69.93% 1040ms 4.27% runtime.runqgrab ``` 不说其他,bytes.Index字节查找这项都比普通pc慢很多了,很不科学 大家忙帮看看这是个啥情况 代码如下: ```go package main import ( "bufio" "bytes" "fmt" "os" "runtime" //"runtime/pprof" "flag" "time" ) var logsChan chan []byte var workQueue chan []byte var completeDecodeJson chan bool var complete chan bool var w *bufio.Writer var wc int = 0 // line num var specialCount int = 0 //以处理行数 var concurrency = 9 var stime time.Time = time.Now() var keyWord []byte func main() { //日志样例,隐去了其余字段,实际一条约350字节 //2016/08/18 11:48:19 {"date":"2016-08-18 11:48:19","log":"money","id":400} // f, _ := os.Create("profile_file") // pprof.StartCPUProfile(f) // 开始cpu profile,结果写到文件f中 // defer pprof.StopCPUProfile() // 结束profile runtime.GOMAXPROCS(runtime.NumCPU() - 1) //cpu-1效率更高 defer TimeoutWarning("total time", stime) var logFile = flag.String("f", "log.txt", "log file path") var logTypeP = flag.String("t", "money", "logtype") flag.Parse() logsChan = make(chan []byte, 10000) workQueue = make(chan []byte) completeDecodeJson = make(chan bool) complete = make(chan bool) logType := *logTypeP keyWord = []byte(fmt.Sprintf(`"log":"%s"`, logType)) f, err := os.OpenFile(*logTypeP+".txt", os.O_CREATE|os.O_RDWR, 0660) if err != nil { fmt.Println("create output file error") } defer f.Close() w = bufio.NewWriter(f) logObj, err := os.Open(*logFile) check(err) defer logObj.Close() scanner := bufio.NewScanner(logObj) go func() { for scanner.Scan() { s := scanner.Bytes() logsChan <- append([]byte{}, s...) //必须将s拷贝走,否则下次range会改变bytes指针指向 wc++ } close(logsChan) fmt.Println("readall time:", time.Now().Sub(stime).Seconds()) fmt.Println("total lines:", wc) }() if err := scanner.Err(); err != nil { fmt.Fprintln(os.Stderr, "reading standard input:", err) } go findSpecial() go finishDecode() go output() <-complete } func findSpecial() { for i := 0; i < concurrency; i++ { go func() { for log := range logsChan { if bytes.Index(log, keyWord) != -1 { workQueue <- log } } completeDecodeJson <- true }() } } func finishDecode() { for i := 0; i < concurrency; i++ { <-completeDecodeJson } close(workQueue) //无长度的channel必须关闭后,workQueue才能结束 fmt.Println("deceode time:", time.Now().Sub(stime).Seconds()) } func output() { for line := range workQueue { w.Write(append(line[20:], []byte{0xa}...)) } w.Flush() complete <- true } func check(e error) { if e != nil { panic(e) } } func TimeoutWarning(tag string, start time.Time) { dis := time.Now().Sub(start).Seconds() fmt.Println(tag, dis) } ```
已邀请:

akin520

赞同来自: wulinlw

PC的CPU HZ比服务器的要高很多,PC 3.4 SERVER 2.4 2.0

stevewang

赞同来自: raindylong

总结一下我的观点:
1.虽然服务器有24核,但是程序里的并行数主要是由`concurrency`来决定的,而这个数值固定为9
2.findSpecial这个goroutine的计算太少,只是执行语句`bytes.Index`而已,反而channel之间消息传递导致的负载要远远高于这个逻辑计算。也就是说,这么小的计算量不值得单独用goroutine执行。
3.用于连接生产者和消费者goroutine的`workQueue`这个channel应该是带缓存队列的,这样才能让生产者和消费者各自以自己最大的速度执行。
4.一种比较合理的并发模型是对原始文件进行拆分(通过读指针或者分拆成小文件),每个部分用一个goroutine去处理,然后共用一个消费者goroutine把日志写入文件。
还没细看代码,至少你这个`workQueue`应该改成一个长度大一些的带缓冲的channel。
你这个并发模型不是很合理,其实时间主要是消耗在I/O上,但是你的第一个生产者却是单线程,然后依次读取日志,下游的findSpecial其实消耗cpu不多,反而有那么多并发执行。
在服务器上做了一个更细致的测试,
单独扫一次文件0.4s
```go
for scanner.Scan() {
//do nothing
}
```
日志查找300W次0.2s
```go
func getlog3() {
defer TimeoutWarning("contains", time.Now())
log := []byte(`{"date":"2016-08-31 00:00:05","log":"money","sid":400}`)

var i int = 0
for i = 0; i < 3000000; i++ {
if bytes.Index(log, keyWord) != -1 {

}
}
fmt.Println(i)
}
```
把这2个工作放一起,3.3s
```go
var s []byte
for scanner.Scan() {
s = append([]byte{}, scanner.Bytes()...)
if bytes.Index(s, keyWord) != -1 {
}
}
```
此时的pprof
```go
pprof) top 10
4540ms of 6850ms total (66.28%)
Dropped 68 nodes (cum <= 34.25ms)
Showing top 10 nodes out of 93 (cum >= 240ms)
flat flat% sum% cum cum%
1290ms 18.83% 18.83% 2650ms 38.69% bytes.Index
890ms 12.99% 31.82% 890ms 12.99% runtime.indexbytebody
530ms 7.74% 39.56% 530ms 7.74% runtime/internal/atomic.Xchg
430ms 6.28% 45.84% 430ms 6.28% runtime.memeqbody
320ms 4.67% 50.51% 590ms 8.61% runtime.lock
310ms 4.53% 55.04% 360ms 5.26% syscall.Syscall
210ms 3.07% 58.10% 210ms 3.07% runtime.memmove
210ms 3.07% 61.17% 210ms 3.07% runtime.osyield
180ms 2.63% 63.80% 350ms 5.11% runtime.mallocgc
170ms 2.48% 66.28% 240ms 3.50% runtime.runqgrab
```
时间都哪儿去了?奇葩的情况啊
是cpu频率的问题吗
这段代码主要由几个瓶颈

1. `s = append([]byte{}, scanner.Bytes()...)` 相当于 new 了行数次,这个浪费了CPU
2. `logsChan <- s` 这个已经接下来的取队列,都是比较占CPU的

这个例子,直接在主线程里做查找是最省时间的,但还是比grep慢一些。
当处理时间`Bytes.Index` 远小于 new 和 出入 chan 时,最好直接干。
如果文件实在太大,需要多线程处理,最好也如 @stevewang 所说的
```
4.一种比较合理的并发模型是对原始文件进行拆分(通过读指针或者分拆成小文件),每个部分用一个goroutine去处理,
```

另外,这个程序的瓶颈绝对不是IO,而是IO比处理快太多了。

补充一下
服务器比pc慢的原因可能是服务器的核数太多了,对于你的场景,线程切换的成本是需要考虑的。

raindylong - 学习go的路上,盼望登顶的一天

我是猜的,代码没有利用所有的CPU资源,而且你本地的i5比服务器的CPU主频要高。。。
猜的。。。

要回复问题请先登录注册