incubator-cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Aaron Turner <synfina...@gmail.com>
Subject One node hammered?
Date Sat, 23 Jun 2012 01:40:14 GMT
So trying to understand why I'm seeing one or two nodes getting
hammered when I have a batch job running.  By "hammered" I mean Disk
IO load is at or near 100% and CPU load is around 10.0-17.0 while the
vast majority of my nodes have a CPU load between 1-2.  The node(s)
hammered seems to move around during the job.  A few minutes on one
node, then it stabilizes and the problem moves to a different one or
two.  Sometimes the load across all my nodes is back to 1-2 even
though the job is running just as quickly as before.

The job at hand, takes a row KeyA in one CF (like InterfaceDaily), and
writes it as a single column in another CF (like
InterfaceDailyCompressed) to row KeyB and then deletes the original
row KeyA.  Using the random partitioner so I would think that read &
writes would be well distributed over my 9 nodes (RF=3).  The amount
of data read and written is pretty small (2304 bytes written read from
288 cols x 8 bytes each).  My job is multi-threaded, but I've reduced
the number of threads from 20 to 5 and while things seem a little
better, it's hardly 4x better and things are taking about 4x as long.

Client is using Hector 1.0.5 and servers are running Cassandra 1.0.9.

On the effected node will start generating logs like this:

 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,626 MessagingService.java
(line 607) 616 READ messages dropped in last 5000ms
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,627 StatusLogger.java
(line 50) Pool Name                    Active   Pending   Blocked
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,627 StatusLogger.java
(line 65) ReadStage                        16      4628         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,627 StatusLogger.java
(line 65) RequestResponseStage              0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,627 StatusLogger.java
(line 65) ReadRepairStage                   0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,628 StatusLogger.java
(line 65) MutationStage                     0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,628 StatusLogger.java
(line 65) ReplicateOnWriteStage             0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,628 StatusLogger.java
(line 65) GossipStage                       0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,628 StatusLogger.java
(line 65) AntiEntropyStage                  0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,628 StatusLogger.java
(line 65) MigrationStage                    0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,628 StatusLogger.java
(line 65) StreamStage                       0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,628 StatusLogger.java
(line 65) MemtablePostFlusher               0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,629 StatusLogger.java
(line 65) FlushWriter                       0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,629 StatusLogger.java
(line 65) MiscStage                         0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,629 StatusLogger.java
(line 65) InternalResponseStage             0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,629 StatusLogger.java
(line 65) HintedHandoff                     0         0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,629 StatusLogger.java
(line 70) CompactionManager                 0         0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,629 StatusLogger.java
(line 82) MessagingService                n/a       0,0
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,629 StatusLogger.java
(line 86) ColumnFamily                Memtable ops,data  Row cache
size/cap  Key cache size/cap
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,629 StatusLogger.java
(line 89) system.NodeIdInfo                         0,0
 0/0                 1/1
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,630 StatusLogger.java
(line 89) system.IndexInfo                          0,0
 0/0                 0/1
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,630 StatusLogger.java
(line 89) system.LocationInfo                       0,0
 0/0                 1/1
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,630 StatusLogger.java
(line 89) system.Versions                           0,0
 0/0                 0/3
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,630 StatusLogger.java
(line 89) system.Migrations                         0,0
 0/0                 0/1
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,630 StatusLogger.java
(line 89) system.HintsColumnFamily                  0,0
 0/0                 1/1
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,630 StatusLogger.java
(line 89) system.Schema                             0,0
 0/0                 1/1
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,630 StatusLogger.java
(line 89) spider3.MetroFabricDailyAgg     124884,59346265
   0/0         8228/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,630 StatusLogger.java
(line 89) spider3.FabricDailyAggCompressed                 0,0
        0/0            0/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,630 StatusLogger.java
(line 89) spider3.IbxFabricDailyAgg     116794,45801943
 0/0        16311/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,630 StatusLogger.java
(line 89) spider3.DeviceDailyAgg        121624,73123817
 0/0        61037/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,631 StatusLogger.java
(line 89) spider3.IbxFabricDailyAggCompressed        6016,8819380
           0/0         1317/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,631 StatusLogger.java
(line 89) spider3.Meta                    2094,16880922
 0/0         8768/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,631 StatusLogger.java
(line 89) spider3.FabricDailyAgg                    0,0
 0/0            0/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,631 StatusLogger.java
(line 89) spider3.InterfaceDailyCompressed      50900,57986845
        0/0       200000/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,631 StatusLogger.java
(line 89) spider3.DeviceDailyAggCompressed      35282,59557567
        0/0         7629/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,631 StatusLogger.java
(line 89) spider3.TrunklessDeviceDailyAgg      69603,47157326
       0/0        31600/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,631 StatusLogger.java
(line 89) spider3.LastStat                    32,936460
 0/0        19777/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,631 StatusLogger.java
(line 89) spider3.RegionFabricDailyAggCompressed         686,1191802
              0/0          147/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,631 StatusLogger.java
(line 89) spider3.TrunklessDeviceDailyAggCompressed
14144,23056640                 0/0         3058/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,631 StatusLogger.java
(line 89) spider3.RegionFabricDailyAgg      94085,12703937
    0/0         1627/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,632 StatusLogger.java
(line 89) spider3.DeviceFabricDailyAgg       10779,5941110
    0/0        31033/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,632 StatusLogger.java
(line 89) spider3.InterfaceDaily       280817,145511376
 0/0       200000/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,632 StatusLogger.java
(line 89) spider3.DeviceFabricDailyAggCompressed      15179,20592356
              0/0         3229/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,632 StatusLogger.java
(line 89) spider3.MetroFabricDailyAggCompressed        3032,4568080
             0/0          642/200000
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,632 StatusLogger.java
(line 89) OpsCenter.rollups60          218594,158987534
 0/0               50/50
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,632 StatusLogger.java
(line 89) OpsCenter.events_timeline                 0,0
 0/0                 0/5
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,632 StatusLogger.java
(line 89) OpsCenter.rollups300           91185,71822435
 0/0               32/50
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,632 StatusLogger.java
(line 89) OpsCenter.pdps                312736,62115027
 0/0               0/300
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,632 StatusLogger.java
(line 89) OpsCenter.events                          0,0
 0/0                6/50
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,632 StatusLogger.java
(line 89) OpsCenter.settings                        0,0
 0/0                0/50
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,633 StatusLogger.java
(line 89) OpsCenter.rollups7200            3908,3024712
 0/0                0/50
 INFO [ScheduledTasks:1] 2012-06-22 17:55:18,633 StatusLogger.java
(line 89) OpsCenter.rollups86400             796,608956
 0/0                0/50

Looking at the logs, I don't see any compactions or repairs going on.
Anyways, how should I debug this further to see what is causing this?


-- 
Aaron Turner
http://synfin.net/         Twitter: @synfinatic
http://tcpreplay.synfin.net/ - Pcap editing and replay tools for Unix & Windows
Those who would give up essential Liberty, to purchase a little temporary
Safety, deserve neither Liberty nor Safety.
    -- Benjamin Franklin
"carpe diem quam minimum credula postero"

Mime
View raw message