leveldb writes blocks occassionarily

[GoogleCodeExporter]

What steps will reproduce the problem?
1. download and compile leveldb-1.9.0
2. write a test program test.cpp(in attachment), which makes only Put() 
operations.
3. compile and run the test

What is the expected output? What do you see instead?

All write operations should be quick enougth(less than 100ms), there should not 
print any slow log.

Here the outputs:

nums: 1000
   83: slow log: 7151.075
  169: slow log:  106.461
  403: slow log:  393.466
  487: slow log:  112.986
  563: slow log:  117.801

the slowest write operation takes 7151.075 ms!

What version of the product are you using? On what operating system?

Linux xen05.wd.corp.qihoo.net 2.6.18-164.el5xen #1 SMP Thu Sep 3 04:03:03 EDT 
2009 x86_64 x86_64 x86_64 GNU/Linux

Please provide any additional information below.

How to compile test.cpp: g++ test.cpp -I../leveldb-1.9.0/include 
../leveldb-1.9.0/libleveldb.a -pthread
Run it: ./a.out

Original issue reported on code.google.com by wuzuy...@gmail.com on 3 May 2013 at 6:55

[GoogleCodeExporter]

The attachment may be mission, repost.

{{{
#include <stdio.h>
#include <stdint.h>
#include <stdlib.h>
#include <time.h>
#include <sys/time.h>

#include <string>

#include "leveldb/db.h"
#include "leveldb/options.h"
#include "leveldb/slice.h"

static inline double microtime(){
    struct timeval now;
    gettimeofday(&now, NULL);
    double ret = now.tv_sec + now.tv_usec/1000.0/1000.0;
    return ret;
}
int main(int argc, char **argv){
    int nums = 1000;
    if(argc > 1){
        nums = atoi(argv[1]);
    }
    printf("nums: %d\n", nums);

    leveldb::DB* db;
    leveldb::Options options;
    leveldb::Status status;
    options.create_if_missing = true;
    status = leveldb::DB::Open(options, "a", &db);
    if(!status.ok()){
        printf("open leveldb: %s error!\n", "a");
        return 0;
    }

    char buf[1024];
    srand ( time(NULL) );

    for(int i=0; i<nums; i++){
        snprintf(buf, sizeof(buf), "%d%d", rand(), rand());
        std::string k(buf);
        std::string v(rand()%(100*1024), 'a');
        double stime = microtime();
        status = db->Put(leveldb::WriteOptions(), k, v);
        double ts = 1000 * (microtime() - stime);
        if(ts > 100){
            printf("%5d: slow log: %8.3f\n", i, ts);
        }
        if(!status.ok()){
            printf("put leveldb error!\n");
            break;
        }
    }

    delete db;
    return 0;
}
}}}

Original comment by wuzuy...@gmail.com on 3 May 2013 at 6:57

Attachments:

• test.cpp

[GoogleCodeExporter]

I put debug codes in db_impl.cc, I can see DBImpl::MakeRoomForWrite(bool force) 
takes most of the time.

And these lines got executed many times within one Write:

      // There are too many level-0 files.
      Log(options_.info_log, "waiting...\n");
      bg_cv_.Wait();

As the comment show, I think there is something related to background 
compaction thread. Maybe leveldb shouldn't wait for compaction to complete? 

Original comment by wuzuy...@gmail.com on 3 May 2013 at 7:54

[GoogleCodeExporter]

Original comment by dgrogan@chromium.org on 3 May 2013 at 5:53