Replikation stürzt ab, Performanceproblem und unbekannter Traffic

[csternberg]

Hallo,

wir haben hier 2 RS2212+ als Backupmaschinen mit einer Nettokapazität von je 16 TB wovon auf der einen 11 TB belegt sind. Die zweite soll eigentlich als zusätzliches Backup in einem zweiten Brandabschnitt per Replikation ("Synchronisierung von gemeinsamen Ordnern") dienen. Das Dumme ist nur, dass der rsync von der einen auf die andere regelmäßig abstürzt. Hier der dazugehörige (längliche) Log aus /var/log/messages:

23:36:49 kernel: [2275102.872747] postgres invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0
23:36:49 kernel: [2275102.880271] Pid: 21537, comm: postgres Tainted: P           2.6.32.12 #2228
23:36:49 kernel: [2275102.887577] Call Trace:
23:36:49 kernel: [2275102.890252]  [<ffffffff8107368f>] ? oom_kill_process+0x12f/0x220
23:36:49 kernel: [2275102.896545]  [<ffffffff81073dab>] ? __out_of_memory+0x3b/0xb0
23:36:49 kernel: [2275102.902586]  [<ffffffff81073f0e>] ? out_of_memory+0x5e/0xb0
23:36:49 kernel: [2275102.908448]  [<ffffffff81076225>] ? __alloc_pages_nodemask+0x605/0x620
23:36:49 kernel: [2275102.915303]  [<ffffffff8106f950>] ? sync_page+0x0/0x50
23:36:49 kernel: [2275102.920737]  [<ffffffff81078cac>] ? __do_page_cache_readahead+0xdc/0x210
23:36:49 kernel: [2275102.927768]  [<ffffffff8104e1c0>] ? wake_bit_function+0x0/0x30
23:36:49 kernel: [2275102.933909]  [<ffffffff81078dfc>] ? ra_submit+0x1c/0x30
23:36:49 kernel: [2275102.939409]  [<ffffffff810714b2>] ? filemap_fault+0x372/0x3d0
23:36:49 kernel: [2275102.945460]  [<ffffffff81086825>] ? __do_fault+0x55/0x470
23:36:50 kernel: [2275102.951168]  [<ffffffff8108746e>] ? handle_mm_fault+0x17e/0x790
23:36:50 kernel: [2275102.957387]  [<ffffffff810557aa>] ? ktime_get_ts+0x5a/0xd0
23:36:50 kernel: [2275102.963191]  [<ffffffff810d8d10>] ? poll_select_copy_remaining+0xb0/0x130
23:36:50 kernel: [2275102.970321]  [<ffffffff81025be8>] ? do_page_fault+0x138/0x300
23:36:50 kernel: [2275102.976358]  [<ffffffff8131b7df>] ? page_fault+0x1f/0x30
23:36:50 kernel: [2275102.984483] DMA per-cpu:
23:36:50 kernel: [2275102.987255] CPU    0: hi:    0, btch:   1 usd:   0
23:36:49 s2s_syncer: netbkp_rsync_execv.c:172 child didn't terminate normally.
23:36:50 s2s_syncer: netbkp_rsync_execv.c:177 child process was terminated by signal 9.
23:36:50 kernel: [2275102.992348] CPU    1: hi:    0, btch:   1 usd:   0
23:36:50 kernel: [2275102.997469] CPU    2: hi:    0, btch:   1 usd:   0
23:36:50 kernel: [2275103.002565] CPU    3: hi:    0, btch:   1 usd:   0
23:36:50 kernel: [2275103.007647] DMA32 per-cpu:
23:36:50 kernel: [2275103.010593] CPU    0: hi:  186, btch:  31 usd: 183
23:36:50 kernel: [2275103.015722] CPU    1: hi:  186, btch:  31 usd: 210
23:36:50 kernel: [2275103.020798] CPU    2: hi:  186, btch:  31 usd: 182
23:36:50 kernel: [2275103.025892] CPU    3: hi:  186, btch:  31 usd: 177
23:36:50 kernel: [2275103.031006] active_anon:108112 inactive_anon:108190 isolated_anon:0
23:36:50 kernel: [2275103.031008]  active_file:1196 inactive_file:1232 isolated_file:0
23:36:50 kernel: [2275103.031010]  unevictable:0 dirty:0 writeback:0 unstable:0
23:36:50 kernel: [2275103.031011]  free:2973 slab_reclaimable:1066 slab_unreclaimable:11816
23:36:50 kernel: [2275103.031013]  mapped:296 shmem:505 pagetables:1850 bounce:0
23:36:50 kernel: [2275103.062240] DMA free:4040kB min:120kB low:148kB high:180kB active_anon:5356kB inactive_anon:5572kB active_file:8kB inactive_file:12kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15368kB mlocked:0kB dirty:
23:36:50 kernel: [2275103.100423] lowmem_reserve[]: 0 982 982 982
23:36:50 kernel: [2275103.104996] DMA32 free:7728kB min:8068kB low:10084kB high:12100kB active_anon:427092kB inactive_anon:427188kB active_file:4776kB inactive_file:4916kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:1006216kB
23:36:50 kernel: [2275103.146470] lowmem_reserve[]: 0 0 0 0
23:36:50 kernel: [2275103.150543] DMA: 10*4kB 2*8kB 1*16kB 0*32kB 0*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 4040kB
23:36:50 kernel: [2275103.161275] DMA32: 920*4kB 0*8kB 1*16kB 0*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 7728kB
23:36:50 kernel: [2275103.172296] 4105 total pagecache pages
23:36:50 kernel: [2275103.176315] 1168 pages in swap cache
23:36:50 kernel: [2275103.180169] Swap cache stats: add 2520479, delete 2519311, find 1696212/1918812
23:36:50 kernel: [2275103.187837] Free swap  = 0kB
23:36:50 kernel: [2275103.190964] Total swap = 2097080kB
23:36:50 kernel: [2275103.214452] Out of memory: kill process 24344 (s2s_syncer) score 7741 or a child
23:36:50 kernel: [2275103.222263] Killed process 24374 (s2s_syncer)
23:36:50 kernel: [2275103.661224] rsync invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0
23:36:50 kernel: [2275103.668404] Pid: 5934, comm: rsync Tainted: P           2.6.32.12 #2228
23:36:50 kernel: [2275103.675312] Call Trace:
23:36:50 kernel: [2275103.677998]  [<ffffffff8107368f>] ? oom_kill_process+0x12f/0x220
23:36:50 kernel: [2275103.684309]  [<ffffffff81073dab>] ? __out_of_memory+0x3b/0xb0
23:36:50 kernel: [2275103.690346]  [<ffffffff81073f0e>] ? out_of_memory+0x5e/0xb0
23:36:50 kernel: [2275103.696229]  [<ffffffff81076225>] ? __alloc_pages_nodemask+0x605/0x620
23:36:50 kernel: [2275103.703073]  [<ffffffff8106f950>] ? sync_page+0x0/0x50
23:36:50 kernel: [2275103.708495]  [<ffffffff81078cac>] ? __do_page_cache_readahead+0xdc/0x210
23:36:50 kernel: [2275103.715522]  [<ffffffff8104e1c0>] ? wake_bit_function+0x0/0x30
23:36:50 kernel: [2275103.721662]  [<ffffffff81078dfc>] ? ra_submit+0x1c/0x30
23:36:50 kernel: [2275103.727181]  [<ffffffff810714b2>] ? filemap_fault+0x372/0x3d0
23:36:50 kernel: [2275103.733228]  [<ffffffff81086825>] ? __do_fault+0x55/0x470
23:36:50 kernel: [2275103.738910]  [<ffffffff8108746e>] ? handle_mm_fault+0x17e/0x790
23:36:50 kernel: [2275103.745123]  [<ffffffff81025be8>] ? do_page_fault+0x138/0x300
23:36:50 kernel: [2275103.751169]  [<ffffffff8131b7df>] ? page_fault+0x1f/0x30
23:36:50 kernel: [2275103.759274] DMA per-cpu:
23:36:50 kernel: [2275103.762030] CPU    0: hi:    0, btch:   1 usd:   0
23:36:50 kernel: [2275103.767098] CPU    1: hi:    0, btch:   1 usd:   0
23:36:50 kernel: [2275103.772151] CPU    2: hi:    0, btch:   1 usd:   0
23:36:50 kernel: [2275103.777224] CPU    3: hi:    0, btch:   1 usd:   0
23:36:50 kernel: [2275103.782300] DMA32 per-cpu:
23:36:50 kernel: [2275103.785247] CPU    0: hi:  186, btch:  31 usd: 156
23:36:50 kernel: [2275103.790306] CPU    1: hi:  186, btch:  31 usd: 154
23:36:50 kernel: [2275103.795356] CPU    2: hi:  186, btch:  31 usd: 174
23:36:50 kernel: [2275103.800424] CPU    3: hi:  186, btch:  31 usd: 160
23:36:50 kernel: [2275103.805488] active_anon:108070 inactive_anon:108167 isolated_anon:0
23:36:50 kernel: [2275103.805490]  active_file:1129 inactive_file:1071 isolated_file:0
23:36:50 kernel: [2275103.805492]  unevictable:0 dirty:0 writeback:0 unstable:0
23:36:50 kernel: [2275103.805494]  free:3004 slab_reclaimable:1066 slab_unreclaimable:11833
23:36:50 kernel: [2275103.805496]  mapped:185 shmem:505 pagetables:1850 bounce:0
23:36:50 kernel: [2275103.836530] DMA free:4040kB min:120kB low:148kB high:180kB active_anon:5356kB inactive_anon:5572kB active_file:8kB inactive_file:112kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15368kB mlocked:0kB dirty
23:36:50 kernel: [2275103.874658] lowmem_reserve[]: 0 982 982 982
23:36:50 kernel: [2275103.879260] DMA32 free:7976kB min:8068kB low:10084kB high:12100kB active_anon:426924kB inactive_anon:427096kB active_file:4508kB inactive_file:4172kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:1006216kB
23:36:50 kernel: [2275103.920285] lowmem_reserve[]: 0 0 0 0
23:36:50 kernel: [2275103.924345] DMA: 10*4kB 2*8kB 1*16kB 0*32kB 0*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 4040kB
23:36:50 kernel: [2275103.935012] DMA32: 951*4kB 0*8kB 1*16kB 0*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 7852kB
23:36:50 kernel: [2275103.945907] 3909 total pagecache pages
23:36:50 kernel: [2275103.949904] 1173 pages in swap cache
23:36:50 kernel: [2275103.953716] Swap cache stats: add 2520497, delete 2519324, find 1696212/1918812
23:36:50 kernel: [2275103.961347] Free swap  = 0kB
23:36:50 kernel: [2275103.964458] Total swap = 2097080kB
23:36:50 kernel: [2275103.987772] Out of memory: kill process 24344 (s2s_syncer) score 7712 or a child
23:36:50 kernel: [2275103.995491] Killed process 24385 (rsync)
23:36:50 s2s_syncer: sync share:[/volume1/backup] failed.  ret=[-1]

Ich habe grad nochmal nachgeschaut: Das passierte, während der "rm -rf" von rsnapshot durchgeführt wurde (siehe Problem 2)

Das zweite Problem:

Die erste Maschine macht das Backup von unserem EMC-Main-Storage per rsnapshot (rsync script). Dabei werden bei jedem backup neue Ordner angelegt und für unveränderte Files Hardlinks zum bestehenden Ordner. Das klappt auch. Dabei ist eingestellt, wieviele Backups aufgehoben werden sollen. Und hier kommt das Problem: Bei diesem Vorgang wird das jeweils älteste Backup per "rm -rf" gelöscht und dieser Löschvorgang dauert geschlagene 3 1/2 Stunden. Ist das normal?

Und Nummer drei:

Auf der ersten Maschine habe ich laut Ressourcen-Monitor einen permanenten Downstream auf NIC1 (die Backups laufen über ein extra Netz mit separatem Switch über NIC2) von ca. 22KB/s (sind das eigentlich Byte od. Bit?) und ich kriege beim besten willen nicht raus, was das ist. Es ist zwar auch noch die Surveillance Station installiert, aber der Downstream bricht auch nicht ab, wenn ich die stoppe. Ich habe schon iftop installiert, aber das funktioniert nicht bzw. zeigt überall nur "0" an.

Danke schonmal für Unterstützung,
Christoph Sternberg

 

[jahlives]

arbeitest du mit dem Programm rsnapshot oder mit einem eigenen rsync Script welches du rsnapshot nennst? Beim Programm rsnaphot kenne ich extreme Laufzeiten wenn ein alter Snapshot gelöscht wird. Das kann sehr sehr lange dauern, je nachdem wie gross der Snapshot ist. Habe ich bei meinem Backup mit rsnapshot auch schon gehabt (ging sicher mehr als 2h). Bei mir ist es an einer "falschen" Konfig im rsnapshot.conf gelegen. rsnapshot ist sehr heikel auf die definierten Intervalle in der Konfig im Zusammenspiel mit den cronjobs welche die verschiedenen Intervalle aufrufen.
wie sehen denn die Intervalle in der Konfig und die cronjobs bei dir aus?

 

[csternberg]

Es ist das "echte" rsnapshot.

rsnapshot backup intervals:

interval        hourly  2
interval        daily   7
interval        weekly  4
interval        monthly 3

Meine crontab:

0       11      *       *       *       root    /opt/bin/rsnapshot hourly
0       21      *       *       *       root    /opt/bin/rsnapshot hourly
30      5       *       *       *       root    /opt/bin/rsnapshot daily
30      7       *       *       6       root    /opt/bin/rsnapshot weekly
30      6       1       *       *       root    /opt/bin/rsnapshot monthly

Durch die lange Laufzeit des rm -rf kommt sich das alles ins Gehege.

 

[jahlives]

wieviele hourly hast du jetzt aktuell im Backupverzeichnis? Sollte nur einer sein. Ich würde zudem die anderen Intervalle näher an den ersten hourly bringen z.B. den daily um 10:40 den weekly um 10:30 und den monthly um 10:20.
hintergrund: die höheren Intervalle sollten vor den kleineren stattfinden. Denn die höheren nehmen einfach den letzten Snapshot des nächst tieferen Intervalls und benennen den um. Das geht sehr schnell. Nur die hourly Backups laufen recht lang, die höheren Intervalle müssen im Idealfall nur einen Snapshot umbenennen und sind fertig. Löschen müssen die Intervalle eigentlich erst wenn zuviele Snapshots des Vorgängerintervalls vorhanden sind.
Könnte es bei dir eventuell sein, dass du aktuell bereits 2 hourly im Backupverzeichnis hast?

 

[csternberg]

Stimmt, die Optimierung der Zeitpunkte der höheren Intervalle hatte ich mir auch schon vorgenommen. Kann es sein, dass die Abstürze der Replikation zur zweiten Maschine mit dem parallelen rm zusammenhängen? Aber spätestens beim 4. "monthly" muss er dann aber doch ein rm machen. Dass das aber 3 1/2 Stunden dauern kann hätte ich nie gedacht.

Bliebe dann noch die Frage zu dem permanenten Traffic auf NIC1 und ob da eigentlich KBit od. KByte im Ressourcenmonitor angezeigt werden. Aufgrund des großen "B" hätte ich jetzt auf KByte getippt.

 

[csternberg]

Ich hab's mir jetzt doch nochmal durch den Kopf gehen lassen: Das Löschen muss spätestens ab dann, wenn die definierte Anzahl Backups des jeweiligen Intervalls erreicht ist, immer bei jedem Intervall: Ältestes Backup (das mit der höchsten Nummer) löschen, alle übrigen eine Nummer höher shiften und das höchste des niedrigeren Intervalls zu .0 machen. Und bei bis zu 3 1/2 Stunden Löschdauer wird's verdammt schwierig, das zeitlich hinzukriegen.