Skip to content

Commit

Permalink
add some logging on timing information
Browse files Browse the repository at this point in the history
  • Loading branch information
Dean Hiller committed Aug 19, 2012
1 parent 1bc6146 commit 98b316c
Show file tree
Hide file tree
Showing 2 changed files with 61 additions and 14 deletions.
37 changes: 30 additions & 7 deletions input/javasrc/com/alvazan/orm/layer9z/spi/db/cassandra/CassandraSession.java
View file
Expand Up @@ -92,7 +92,14 @@ public Iterable<KeyValue<Row>> findImpl2(String colFamily, Iterable<byte[]> keys
Keyspace keyspace = columnFamilies.getKeyspace();
ColumnFamilyQuery<byte[], byte[]> query = keyspace.prepareQuery(cf);
RowSliceQuery<byte[], byte[]> slice = query.getKeySlice(keys);

long time = System.currentTimeMillis();
OperationResult<Rows<byte[], byte[]>> result = slice.execute();
if(log.isInfoEnabled()) {
long total = System.currentTimeMillis()-time;
log.info("astyanx find took="+total+" ms");
}

Rows rows = result.getResult();

ResultIterable r = new ResultIterable(rowProvider, rows);
Expand Down Expand Up @@ -139,7 +146,13 @@ public void sendChangesImpl(List<Action> actions, NoSqlEntityManager mgr) throws
}
}

long time = System.currentTimeMillis();
m.execute();

if(log.isInfoEnabled()) {
long total = System.currentTimeMillis()-time;
log.info("astyanx save took="+total+" ms");
}
}


Expand Down Expand Up @@ -272,14 +285,14 @@ public Iterable<Column> columnRangeScan(ScanInfo info, Key from, Key to, int bat
ColumnType type = info1.getColumnType();
if(type == ColumnType.ANY_EXCEPT_COMPOSITE) {
ByteBufferRange range = new RangeBuilder().setStart(from.getKey()).setEnd(to.getKey()).setLimit(batchSize).build();
return findBasic(rowKey, range, info1);
return findBasic(rowKey, range, info1, batchSize);

} else if(type == ColumnType.COMPOSITE_INTEGERPREFIX ||
type == ColumnType.COMPOSITE_DECIMALPREFIX ||
type == ColumnType.COMPOSITE_STRINGPREFIX) {
CompositeRangeBuilder range = setupRangeBuilder(from, to, info1);
range = range.limit(batchSize);
return findBasic(rowKey, range, info1);
return findBasic(rowKey, range, info1, batchSize);
} else
throw new UnsupportedOperationException("not done here yet");
}
Expand All @@ -302,7 +315,7 @@ private CompositeRangeBuilder setupRangeBuilder(Key from, Key to, Info info1) {
return range;
}

private Iterable<Column> findBasic(byte[] rowKey, ByteBufferRange range, Info info) {
private Iterable<Column> findBasic(byte[] rowKey, ByteBufferRange range, Info info, int batchSize) {
ColumnFamily cf = info.getColumnFamilyObj();

Keyspace keyspace = columnFamilies.getKeyspace();
Expand All @@ -311,34 +324,38 @@ private Iterable<Column> findBasic(byte[] rowKey, ByteBufferRange range, Info in
.autoPaginate(true)
.withColumnRange(range);

return new OurIter(cf, rowQuery, info);
return new OurIter(cf, rowQuery, info, batchSize);
}

private class OurIter implements Iterable<Column> {

private ColumnFamily cf;
private RowQuery query;
private Info info;
private int batchSize;

public OurIter(ColumnFamily cf, RowQuery query2, Info info) {
public OurIter(ColumnFamily cf, RowQuery query2, Info info, int batchSize2) {
this.cf = cf;
this.query = query2;
this.info = info;
this.batchSize = batchSize2;
}

@Override
public Iterator<Column> iterator() {
return new OurIterator(cf, query, info);
return new OurIterator(cf, query, info, batchSize);
}
}
private class OurIterator implements Iterator<Column> {
private RowQuery<byte[], byte[]> query;
private Iterator<com.netflix.astyanax.model.Column<byte[]>> subIterator;
private Info info;
private int batchSize;

public OurIterator(ColumnFamily cf, RowQuery query, Info info) {
public OurIterator(ColumnFamily cf, RowQuery query, Info info, int batchSize) {
this.query = query;
this.info = info;
this.batchSize = batchSize;
}

@Override
Expand Down Expand Up @@ -400,7 +417,13 @@ private void fetchMoreResultsImpl() throws ConnectionException {
if(subIterator != null && subIterator.hasNext())
return; //no need to fetch more since subIterator has more

long time = System.currentTimeMillis();
ColumnList<byte[]> columns = query.execute().getResult();
if(log.isInfoEnabled()) {
long total = System.currentTimeMillis()-time;
log.info("astyanx column slice took="+total+" ms batchSize="+batchSize);
}

if(columns.isEmpty())
subIterator = null;
else
Expand Down
38 changes: 31 additions & 7 deletions input/javasrc/com/alvazan/orm/logging/NoSqlRawLogger.java
View file
Expand Up @@ -36,10 +36,16 @@ public class NoSqlRawLogger implements NoSqlRawSession {

@Override
public void sendChanges(List<Action> actions, Object ormFromAbove) {
long time = 0;
if(log.isInfoEnabled()) {
logInformation(actions);
time = System.currentTimeMillis();
}
session.sendChanges(actions, ormFromAbove);
if(log.isInfoEnabled()) {
long total = System.currentTimeMillis()-time;
log.info("[rawlogger] Sending Changes to server took(including spi plugin)="+total+" ms");
}
}

private void logInformation(List<Action> actions) {
Expand All @@ -49,6 +55,7 @@ private void logInformation(List<Action> actions) {
log.info("[rawlogger] (exception logging save actions, turn on trace to see)");
}
}

private void logInformationImpl(List<Action> actions) {
String msg = "[rawlogger] Data being flushed to database in one go=";
for(Action act : actions) {
Expand Down Expand Up @@ -127,10 +134,17 @@ private String convert(String cf, byte[] rowKey) {

@Override
public Iterable<Column> columnRangeScan(ScanInfo info, Key from, Key to, int batchSize) {
long time = 0;
if(log.isInfoEnabled()) {
logColScan(info, from, to, batchSize);
time = System.currentTimeMillis();
}
Iterable<Column> ret = session.columnRangeScan(info, from, to, batchSize);
if(log.isInfoEnabled()) {
long total = System.currentTimeMillis()-time;
log.info("[rawsession] column range scan took="+total+" ms");
}
return session.columnRangeScan(info, from, to, batchSize);
return ret;
}

private void logColScan(ScanInfo info, Key from, Key to, int batchSize) {
Expand Down Expand Up @@ -186,10 +200,16 @@ private String logColScanImpl(ScanInfo info, Key from, Key to, int batchSize) {

@Override
public void clearDatabase() {
long time = 0;
if(log.isInfoEnabled()) {
log.info("[rawlogger] clearing database");
time = System.currentTimeMillis();
}
session.clearDatabase();
if(log.isInfoEnabled()) {
long total = System.currentTimeMillis()-time;
log.info("[rawsession] clearDatabase took(including spi plugin)="+total+" ms");
}
}

@Override
Expand All @@ -211,12 +231,16 @@ public void close() {
@Override
public Iterable<KeyValue<Row>> find(String colFamily,
Iterable<byte[]> rowKeys) {
//This iterable allows us to log inline so we don't for loop until the bottom with everyone
//else...We do ONE LOOP at the bottom on all iterators that were proxied up.
Iterable<byte[]> iterProxy = new IterLogProxy("[rawlogger]", databaseInfo, colFamily, rowKeys);
if(log.isInfoEnabled())
return session.find(colFamily, iterProxy);
else
if(log.isInfoEnabled()) {
//This iterable allows us to log inline so we don't for loop until the bottom with everyone
//else...We do ONE LOOP at the bottom on all iterators that were proxied up.
Iterable<byte[]> iterProxy = new IterLogProxy("[rawlogger]", databaseInfo, colFamily, rowKeys);
long time = System.currentTimeMillis();
Iterable<KeyValue<Row>> ret = session.find(colFamily, iterProxy);
long total = System.currentTimeMillis() - time;
log.info("[rawsession] Total find keyset time(including spi plugin)="+total);
return ret;
} else
return session.find(colFamily, rowKeys);
}

Expand Down

0 comments on commit 98b316c

Please sign in to comment.