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

wulinlw · 2016年12月22日 · 最后由 imjj 回复于 2016年12月23日 · 615 次阅读

这个程序是从一个 1.07G(315w 条)的日志文件中查找指定类型的日志,并将指定类型的日志写到独立文件中 日志文件中每行一条 json 日志 日志样例,隐去了其余字段,实际一条约 350 字节

2016/08/18 11:48:19 {"date":"2016-08-18 11:48:19","log":"money","id":400}

在普通公司电脑上跑出来数据 i5 3470,8G,5400 转硬盘

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

在服务器上

[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

(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

(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 慢很多了,很不科学 大家忙帮看看这是个啥情况

代码如下:

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)
}
更多原创文章干货分享,请关注公众号
  • 加微信实战群请加微信(注明:实战群):gocnio

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

还没细看代码,至少你这个workQueue应该改成一个长度大一些的带缓冲的 channel。

你这个并发模型不是很合理,其实时间主要是消耗在 I/O 上,但是你的第一个生产者却是单线程,然后依次读取日志,下游的 findSpecial 其实消耗 cpu 不多,反而有那么多并发执行。

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

总结一下我的观点: 1.虽然服务器有 24 核,但是程序里的并行数主要是由concurrency来决定的,而这个数值固定为 9 2.findSpecial 这个 goroutine 的计算太少,只是执行语句bytes.Index而已,反而 channel 之间消息传递导致的负载要远远高于这个逻辑计算。也就是说,这么小的计算量不值得单独用 goroutine 执行。 3.用于连接生产者和消费者 goroutine 的workQueue这个 channel 应该是带缓存队列的,这样才能让生产者和消费者各自以自己最大的速度执行。 4.一种比较合理的并发模型是对原始文件进行拆分(通过读指针或者分拆成小文件),每个部分用一个 goroutine 去处理,然后共用一个消费者 goroutine 把日志写入文件。

在服务器上做了一个更细致的测试, 单独扫一次文件 0.4s

for scanner.Scan() {
    //do nothing
}

日志查找 300W 次 0.2s

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

var s []byte
    for scanner.Scan() {
        s = append([]byte{}, scanner.Bytes()...)
        if bytes.Index(s, keyWord) != -1 {
        }
    }

此时的 pprof

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 慢的原因可能是服务器的核数太多了,对于你的场景,线程切换的成本是需要考虑的。

需要 登录 后方可回复, 如果你还没有账号请点击这里 注册