leveldb writes blocks occassionarily

[cmumford]

Original issue 164 created by wuzuyang on 2013-05-03T06:55:01.000Z:

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

[cmumford]

Comment #1 originally posted by wuzuyang on 2013-05-03T06:57:03.000Z:

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;
}

[cmumford]

Comment #2 originally posted by wuzuyang on 2013-05-03T07:54:09.000Z:

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?

[MarcSeebold]

I can reproduce that with small key/value pairs.

233 ops max: 327ms 0.75 quantile: 0.045ms 0.9 quantile: 1.051ms std.dev.: 25.637ms median: 0.021ms avg.: 2.531ms

[bwzhang2011]

@cmumford, any update with such issue ? was it fixed in the latest version ?

[cmumford]

Still present in v1.19. Agreed, this is related to compaction, and is a current design limitation of leveldb. I haven't dug into the code far enough to determine how difficult it would be to unblock the log writing from the background compaction.

[woofyzhao]

You might be writing too fast. It's intended to block and wait the underlying compaction to complete in that case.

[varshneydevansh]

are there any little beginner-friendly issues from where I can start with? =)