Re: Slow processing find query

[Adam C]

You will want to do an explain to get how your queries are actually performing, check for proper index use etc.  The getmore you see with a 1ms response time in the log is not the query you are running.   By default your query will only show up in the log if it is slower than 100ms (the default, you can alter with --slowms on startup or turn on/tweak the settings with the profiler).

The other thing to bear in mind is that if your cache is cold, then a query could involve multiple pages to disk to get the data into memory, which will not be fast - what happens if you run the test again immediately afterward - is it fast then?

Also, you will want to check the network latency between your app and the database (assuming they are not on the same host).  There are a couple of other possibilities here, but that should give you a decent place to start from.

Adam

On Monday, August 27, 2012 6:49:22 AM UTC+1, Илья Скорик wrote:

I have small size Collection with ~3000 records like:

{ "_id" : ObjectId( "503aa4deeee88890b069daa4" ),
  "active" : "Y",
  "name" : "CL",
  "pid" : 20,
  "sid" : 2448,
  "slug" : "acura-cl",
  "updated" : Date( 1346020574139 ) }

And simple console application :

Mongo mongo = new Mongo();
DB db = mongo.getDB("database");
DBCollection collection = db.getCollection("importing.website.models");
Long date1 = Calendar.getInstance().getTimeInMillis();
DBCursor cursor = collection.find();
try {
    while(cursor.hasNext()) {
cursor.next();
    }
} finally {
    cursor.close();
}
Long date2 = Calendar.getInstance().getTimeInMillis();
System.out.println(date1);
System.out.println(date2);
System.out.println(date2 - date1);

After starting the application
1346045783973 Date1
1346045784283 Date2
310 ms

In Mongo Server log:

Mon Aug 27 09:36:24 [conn21] run command admin.$cmd { isMaster: 1 }
Mon Aug 27 09:36:24 [conn21] command admin.$cmd command: { isMaster: 1 } ntoreturn:1 reslen:71 0ms
Mon Aug 27 09:36:24 [conn21] query database.importing.website.models nreturned:101 reslen:11727 0ms
Mon Aug 27 09:36:24 [conn21] getmore database.importing.website.models cursorid:6025217777975209934 nreturned:2624 reslen:307474 1ms
Mon Aug 27 09:36:24 [conn21] end connection 127.0.0.1:52587

I run this on macbook pro with corei5, ssd disk.

1ms in Mongo Server vs 210-230 ms in java application? This is the normal 200% overhead for Java?

In a web application for Spring-Data and Spring-MVC handling similar request reaches 300-350 milliseconds, that worries me. 

Or am I doing something wrong? Please help me with this issue.

 

[Илья Скорик]

1. Explain query:

 

> db.importing.website.models.find().explain()
{
"cursor" : "BasicCursor",
"nscanned" : 2725,
"nscannedObjects" : 2725,
"n" : 2725,
"millis" : 1,
"nYields" : 0,
"nChunkSkips" : 0,
"isMultiKey" : false,
"indexOnly" : false,
"indexBounds" : {

}
}
> 

2. Cache?

            for (int c = 1; c <= 10; c++) {
                System.out.println("\n");
                System.out.println("~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~");
                System.out.println("Query = " + c);
                Long date1 = Calendar.getInstance().getTimeInMillis();
                DBCursor cursor = collection.find().limit(3000);
                try {
                    while (cursor.hasNext()) {

                        cursor.next();
                    }
                } finally {
                    cursor.close();
                }
                Long date2 = Calendar.getInstance().getTimeInMillis();

                System.out.println("Time Count = " + (date2 - date1));
                try {
                    Thread.currentThread().sleep(1000);
                }
                catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Query = 1

Time Count = 258

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Query = 2

Time Count = 36

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Query = 3

Time Count = 14

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Query = 4

Time Count = 16

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Query = 5

Time Count = 10

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Query = 6

Time Count = 7

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Query = 7

Time Count = 20

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Query = 8

Time Count = 8

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Query = 9

Time Count = 7

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Query = 10

Time Count = 7

Two questions, why the first query is _always_ so slow? And why do so varies the speed of execution of queries?

3. Yes, DB and Application on localhost

понедельник, 27 августа 2012 г., 13:46:06 UTC+4 пользователь Adam C написал:

[Илья Скорик]

public class App {
    public static void main(String[] args) {
        try {

            Mongo mongo = new Mongo();
            DB db = mongo.getDB("database");

            for (int c = 1; c <= 10; c++) {

                System.out.println("~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~");
                System.out.println("Query = " + c);
                Long date1 = Calendar.getInstance().getTimeInMillis();

                DBCollection collection = db.getCollection("importing.website.models");

                DBCursor cursor = collection.find().limit(-1).skip( 1 + (int)(Math.random() * ((2500 - 1) + 1)) );
                try {
                    while (cursor.hasNext()) {

                        cursor.next();
                    }
                } finally {
                    cursor.close();
                }
                Long date2 = Calendar.getInstance().getTimeInMillis();

                System.out.println("Time Count = " + (date2 - date1));
                try {
                    Thread.currentThread().sleep(1000);
                }
                catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }

        } catch (UnknownHostException e) {
            e.printStackTrace();
        } catch (MongoException e) {
            e.printStackTrace();
        }
    }
}

Result:

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 1
Time Count = 47

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 2
Time Count = 3

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 3
Time Count = 2
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 4
Time Count = 3
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 5
Time Count = 3
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 6
Time Count = 1
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 7
Time Count = 3
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 8
Time Count = 2
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 9
Time Count = 2
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 10
Time Count = 2

The more data, the longer the first one request. Why? 

понедельник, 27 августа 2012 г., 13:46:06 UTC+4 пользователь Adam C написал:

You will want to do an explain to get how your queries are actually performing, check for proper index use etc.  The getmore you see with a 1ms response time in the log is not the query you are running.   By default your query will only show up in the log if it is slower than 100ms (the default, you can alter with --slowms on startup or turn on/tweak the settings with the profiler).

[Rob Moore]

On Monday, August 27, 2012 3:51:58 PM UTC-4, Илья Скорик wrote:

The more data, the longer the first one request. Why? 

For one thing the first rquest has to allocate buffers, create the connection, and other resources the driver pools to make the other requests fasts.

Rob.

[Илья Скорик]

This behavior can be changed? For Web applications, this behavior is bad for performance. Maybe there is something like the pull of ready connections?

вторник, 28 августа 2012 г., 1:07:42 UTC+4 пользователь Rob Moore написал:

[Илья Скорик]

This is the result of ten requests for choosing 2500 elements. It does not appear that the problem is only the first query.

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 1
Time Count = 325
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 2
Time Count = 172
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 3
Time Count = 127
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 4
Time Count = 62
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 5
Time Count = 30
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 6
Time Count = 31
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 7
Time Count = 11
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 8
Time Count = 15
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 9
Time Count = 13
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Query = 10
Time Count = 22

вторник, 28 августа 2012 г., 1:07:42 UTC+4 пользователь Rob Moore написал:

[Илья Скорик]

Same database, same query php5:

  $time1 = microtime();
echo $cursor->count() . " document(s) found.\n"; 
foreach ($cursor as $obj) {
}
  $time2 = microtime();
 
  print ($time2 - $time1) * 1000;

Result:

bash-3.2$ php54 mongotest.php 
2725 document(s) found.
14.795

Why Java version so slow? 

вторник, 28 августа 2012 г., 1:07:42 UTC+4 пользователь Rob Moore написал: