2013-09-24 4 views
3

У меня есть программа, которая прослушивает udp для лог-трафика, пытается его проанализировать, а затем вставить в Redis. На определенном уровне трафика, память, кажется, «взрывается» (быстро увеличить от нескольких сот мегабайтов до гигабайтаgolang взрыва памяти: newdefer

Я схватил профиль кучи вскоре после того, как это происходит, и она возвращает следующее:.

(pprof) top100 -cum 
Total: 1731.3 MB 
    0.0 0.0% 0.0% 1731.3 100.0% gosched0 
    1162.5 67.1% 67.1% 1162.5 67.1% newdefer 
    0.0 0.0% 67.1% 1162.5 67.1% runtime.deferproc 
    0.0 0.0% 67.1% 1162.0 67.1% main.TryParse 
    0.0 0.0% 67.1% 438.0 25.3% runtime.main 
    301.5 17.4% 84.6% 437.5 25.3% main.main 
    136.0 7.9% 92.4% 136.0 7.9% runtime.malg 
    0.0 0.0% 92.4% 136.0 7.9% runtime.newproc 
    0.0 0.0% 92.4% 136.0 7.9% runtime.newproc1 
    1.5 0.1% 92.5% 131.3 7.6% main.RedisCuller 
    0.0 0.0% 92.5% 108.5 6.3% github.com/garyburd/redigo/redis.(*conn).Do 
    0.0 0.0% 92.5% 108.5 6.3% github.com/garyburd/redigo/redis.(*conn).readReply 
    0.0 0.0% 92.5% 108.5 6.3% github.com/garyburd/redigo/redis.(*pooledConnection).Do 
    95.8 5.5% 98.0%  95.8 5.5% cnew 
    0.0 0.0% 98.0%  95.8 5.5% runtime.cnewarray 
    34.0 2.0% 100.0%  34.0 2.0% runtime.convT2E 
    0.0 0.0% 100.0%  0.5 0.0% main.init 
    0.0 0.0% 100.0%  0.5 0.0% net/http/pprof.init 
    0.0 0.0% 100.0%  0.5 0.0% sync.(*Once).Do 
    0.0 0.0% 100.0%  0.5 0.0% syscall.Getenv 
    0.0 0.0% 100.0%  0.5 0.0% time.init 

Когда программа «здоровый» профиль выглядит как:

(pprof) top20 -cum 
Total: 186.7 MB 
    0.0 0.0% 0.0% 186.7 100.0% gosched0 
    0.5 0.3% 0.3% 122.7 65.7% main.RedisCuller 
    0.0 0.0% 0.3% 103.5 55.4% github.com/garyburd/redigo/redis.(*pooledConnection).Do 
    0.0 0.0% 0.3% 103.0 55.2% github.com/garyburd/redigo/redis.(*conn).Do 
    0.0 0.0% 0.3% 103.0 55.2% github.com/garyburd/redigo/redis.(*conn).readReply 
    88.2 47.2% 47.5%  88.2 47.2% cnew 
    0.0 0.0% 47.5%  88.2 47.2% runtime.cnewarray 
    0.0 0.0% 47.5%  57.0 30.5% main.TryParse 
    57.0 30.5% 78.0%  57.0 30.5% newdefer 
    0.0 0.0% 78.0%  57.0 30.5% runtime.deferproc 
    34.0 18.2% 96.3%  34.0 18.2% runtime.convT2E 
    1.5 0.8% 97.1%  6.5 3.5% main.main 
    0.0 0.0% 97.1%  6.5 3.5% runtime.main 
    5.0 2.7% 99.7%  5.0 2.7% runtime.malg 
    0.0 0.0% 99.7%  5.0 2.7% runtime.newproc 
    0.0 0.0% 99.7%  5.0 2.7% runtime.newproc1 
    0.0 0.0% 99.7%  0.5 0.3% bufio.NewWriter 
    0.0 0.0% 99.7%  0.5 0.3% bufio.NewWriterSize 
    0.0 0.0% 99.7%  0.5 0.3% github.com/garyburd/redigo/redis.(*Pool).get 
    0.0 0.0% 99.7%  0.5 0.3% github.com/garyburd/redigo/redis.(*pooledConnection).get 

единственный Defer у меня в коде окружающей функции синтаксического анализа (так как он может часто не):

for { 
      rlen, _, err := sock.ReadFromUDP(buf[0:]) 
      checkError(err) 
      raw := logrow.RawRecord(string(buf[:rlen])) 
      go TryParse(raw, c) 
    } 

    ... 

    func TryParse(raw logrow.RawRecord, c chan logrow.Record) { 
     defer func() { 
       if r := recover(); r != nil { 
         //log.Printf("Failed Parse due to panic: %v", raw) 
         return 
       } 
     }() 
     rec, ok := logrow.ParseRawRecord(raw) 
     if !ok { 
       return 
       //log.Printf("Failed Parse: %v", raw) 
     } else { 
       c <- rec 
     } 
} 

Кто-нибудь видит что-то очевидное Я делаю неправильно, что может привести к внезапному всплеску памяти? Или, может быть, какое-то направление в его закреплении?

Edit (Больше кода вокруг logrow.Record канала):

c := make(chan logrow.Record) 
... 
go RedisInserter(c, bucket, retention, pool) 

func RedisInserter(c chan logrow.Record, bucket, retention int, p *redis.Pool) { 
     for rec := range c { 
       logrow.SendToRedis(rec, bucket, retention, p) 
     } 
} 
+0

Вы закрываете 'c' (' chan' 'logrow.Record')? Если да, то вы откладываете закрытие 'c'? Не уверен, что еще предложить, не видя большего кода. – Intermernet

+0

@Intermernet: Добавлен немного больше кода вокруг этого канала. Я никогда не закрываю его, потому что «должно» произойти, так это то, что канал постоянно заполняется с помощью «go TryParse» и что цикл «RedisInserter» должен потреблять эти строки. Глядя на это сейчас, я мог видеть, что, возможно, logrow.SendToRedis может быть заблокирован, и канал заполняется - но не видите, как это может привести к использованию high newdefer памяти? –

+0

Существует утечка памяти в функции закрытия от закрытия. Какой будет случай, если вы раскоментировали printf .: https://codereview.appspot.com/10784043/ Вы пробовали с подсказкой? – ClojureMostly

ответ

1

Оказалось, утечка в closured отложенной функции (проблема в самой Go), как мы видим в:

defer func() { 
      if r := recover(); r != nil { 
        //log.Printf("Failed Parse due to panic: %v", raw) 
        return 
      } 
    }() 

Так что перестройка с использованием последней версии Go разрешила проблему (ссылка: https://codereview.appspot.com/10784043/). Тем не менее, разумная вещь - это, конечно, дизайн ParseRecordFunction, чтобы он не пытался срезать за пределы и вызывать панику.

Смежные вопросы