incubator-cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Wojciech Meler <wojciech.me...@gmail.com>
Subject Re: Cassandra 1.0 hangs during GC
Date Tue, 17 Jul 2012 12:02:57 GMT
I have similar problem with cassandra 0.8.10. After digging a while
I've found that my problem is somehow related to system page scanning
activities.
After turning on -Xloggc I've found high system cpu usage during
ParNew. After looking into sar -B I've found this:

08:00:08 AM   pgpgin/s pgpgout/s   fault/s  majflt/s  pgfree/s
pgscank/s pgscand/s pgsteal/s    %vmeff
08:00:08 AM   3916.08    962.47   1737.93     31.00   1556.87
0.00   6514.35    789.03     12.11
08:10:06 AM   4753.89   1654.53    502.34     37.57   1296.41
0.00   7074.27    942.17     13.32
08:20:09 AM   4961.67   1062.75    508.87     40.01   1194.93
0.00   7474.82    915.63     12.25
08:30:03 AM   5006.94   1397.18    500.92     39.95   1394.10
0.00   9155.64   1124.52     12.28
08:40:09 AM   5796.97   3312.25    507.73     40.44   1462.88
0.00  59539.87   1173.68      1.97
08:50:08 AM   2354.89    602.84    281.43     19.32    636.23
0.00 2126568.76    331.31      0.02
09:00:08 AM      4.83     73.72     90.16      0.06     61.83
0.00 3626444.63     10.90      0.00
09:10:08 AM      0.87      2.82     81.70      0.01     45.39
0.00 3563230.69      0.03      0.00
09:20:09 AM      0.01      4.12     82.28      0.00     46.45
0.00 3566248.02      0.02      0.00
09:30:07 AM      8.62      3.84    122.97      0.11     65.31
0.00 3569377.35      0.59      0.00
09:40:08 AM      0.49    154.61     84.49      0.01     53.06
0.00 3580618.13      4.20      0.00
09:50:08 AM      0.07      5.25     82.58      0.00     47.76
0.00 3564969.22      0.04      0.00
10:00:08 AM     38.25    205.50    200.00      0.02    161.27
0.00 3580132.24      0.25      0.00
10:10:08 AM      0.59      3.43     97.67      0.02     52.99
0.00 3562920.83      0.04      0.00
10:20:08 AM      1.61      5.74     83.32      0.03     48.05
0.00 3587643.92      0.07      0.00
10:30:08 AM      0.47      3.67     77.19      0.00     44.04
0.00 3568829.92      0.11      0.00
10:40:08 AM      0.26     34.01     77.61      0.01     65.30
0.00 3564740.06     20.00      0.00
10:50:06 AM      0.25      4.76     82.60      0.00     49.48
0.00 3562681.08      2.56      0.00
11:00:08 AM      0.90      3.18     85.22      0.02     46.19
0.00 3559971.42      0.26      0.00
11:10:08 AM      0.05      3.20     81.81      0.00     45.50
0.00 3571435.22      0.03      0.00
11:20:07 AM      0.06      5.09     82.39      0.00     46.57
0.00 3571160.15      0.05      0.00
11:30:08 AM      0.42      3.38     76.75      0.00     43.54
0.00 3550153.01      0.07      0.00
11:40:08 AM      2.25     34.13     80.73      0.02     48.81
0.00 3556773.99      0.16      0.00
11:50:08 AM    143.70    145.63    181.79      0.00    146.17
0.00 3559806.31      0.04      0.00
12:00:08 PM      8.93      4.34   1428.64      0.14    551.37
0.00 3571540.52      0.82      0.00
12:10:08 PM  29038.30  32157.76   2301.36    163.57  17789.40
12155.79 1555422.56  14316.18      0.91
12:20:08 PM  40005.26  33453.59   1175.56    119.07  19402.11
14067.52  27828.66  18016.59     43.00
12:30:08 PM  28625.65  19189.01   1197.00    124.72  12740.11
7576.56  11155.77  11423.98     60.99
12:40:08 PM  14569.77   8156.18   1197.94    115.99  11249.82
1115.44   1493.11   1704.10     65.33
12:50:09 PM  12663.07  12462.00   1159.15     91.80   2798.45
0.00   3701.85   1508.08     40.74
01:00:05 PM  12587.33  10603.46   1117.98    100.40   6279.41
3533.36   3904.89   5156.94     69.33

It's looks like system is busy for 3  hours looking for pages to
free... There was no heavy compaction, unexpected high load - nothing
special but strange kernel behaviour, long ParNew and message drops.
Does your system behave that way?

Regards,
Wojtek

On Tue, Jul 17, 2012 at 10:14 AM, Nikolay Kоvshov <nkovshov@yandex.ru> wrote:
>
> This is a cluster of 2 nodes, each having 8G of operating memory, replicationfactor=2
> Write/read pressure is quite low and almost never exceeds 10/second
>
> From time to time (2-3 times in a month) I see GC activity in logs and for this time
cassandra stops responding to requests which results in a timeout in upper-layer application.
Total time of unavailability can be over 5 minues (like in the following case)
>
> What can I do with that? Wiil it become much worse when my cluster grows up?
>
> INFO [GossipTasks:1] 2012-07-16 13:10:50,055 Gossiper.java (line 736) InetAddress /10.220.50.9
is now dead.
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,056 GCInspector.java (line 123) GC for ParNew:
391383 ms for 1 collections, 2025808488 used; max is 8464105472
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,067 StatusLogger.java (line 50) Pool Name
                   Active   Pending   Blocked
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,071 StatusLogger.java (line 65) ReadStage
                        0         0         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,071 StatusLogger.java (line 65) RequestResponseStage
             0         0         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,072 StatusLogger.java (line 65) ReadRepairStage
                  0         0         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,072 StatusLogger.java (line 65) MutationStage
                    0         0         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,073 StatusLogger.java (line 65) ReplicateOnWriteStage
            0         0         0
>  INFO [GossipStage:1] 2012-07-16 13:10:50,074 Gossiper.java (line 722) InetAddress /10.220.50.9
is now UP
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,075 StatusLogger.java (line 65) GossipStage
                      1        59         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,075 StatusLogger.java (line 65) AntiEntropyStage
                 0         0         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,076 StatusLogger.java (line 65) MigrationStage
                   0         0         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,076 StatusLogger.java (line 65) StreamStage
                      0         0         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,077 StatusLogger.java (line 65) MemtablePostFlusher
              0         0         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,077 StatusLogger.java (line 65) FlushWriter
                      0         0         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,077 StatusLogger.java (line 65) MiscStage
                        0         0         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,078 StatusLogger.java (line 65) InternalResponseStage
            0         0         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,078 StatusLogger.java (line 65) HintedHandoff
                    0         0         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,079 StatusLogger.java (line 69) CompactionManager
              n/a         0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,079 StatusLogger.java (line 81) MessagingService
               n/a       0,0
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,080 StatusLogger.java (line 85) ColumnFamily
               Memtable ops,data  Row cache size/cap  Key cache size/cap
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,080 StatusLogger.java (line 88) Keyspace1.PSS
                36712,343842617                 0/0       97995/1000000
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,085 StatusLogger.java (line 88) Keyspace1.Standard1
         128679,162567721                 0/0           0/1000000
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,085 StatusLogger.java (line 88) system.NodeIdInfo
                        0,0                 0/0                 0/1
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,086 StatusLogger.java (line 88) system.IndexInfo
                         0,0                 0/0                 0/1
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,086 StatusLogger.java (line 88) system.LocationInfo
                      0,0                 0/0                 1/2
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,086 StatusLogger.java (line 88) system.Migrations
                        0,0                 0/0                 3/3
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,087 StatusLogger.java (line 88) system.HintsColumnFamily
               1,528                 0/0                 0/1
>  INFO [ScheduledTasks:1] 2012-07-16 13:10:50,087 StatusLogger.java (line 88) system.Schema
                            0,0                 0/0                 2/3
> -------- Завершение пересылаемого сообщения --------

Mime
View raw message