[JAVA-631] Problems with the first query(s) Created: 29/Aug/12  Updated: 11/Sep/19  Resolved: 30/Aug/12

Status: Closed
Project: Java Driver
Component/s: Performance
Affects Version/s: None
Fix Version/s: None

Type: Task Priority: Major - P3
Reporter: Ilya Skorik Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File App.java     Text File LoginForm.java     Text File LoginForm.java     Text File LoginForm.java     Text File MongoConfig.java     Text File matrix-app.log     Text File matrix-app.log     File mongotest.php    

 Description   

https://groups.google.com/d/topic/mongodb-user/JvlCDGQI65g/discussion

In a simple test Java application first query for 3000 elements occurs within 350-400 ms, the second and subsequent occur faster. In the same PHP application query the results are 10-15ms. This is a very serious limitation for web applications.

I'm not sure that this is normal behavior for java driver. What could be wrong?



 Comments   
Comment by Jeffrey Yemin [ 30/Aug/12 ]

It's not a client OS issue. You just need to increase connectionsPerHost in MongoOptions to ensure there are enough connections to adequately account for the number of threads in the app server that are concurrently using Mongo.

Comment by Ilya Skorik [ 30/Aug/12 ]

Thank you all for your participation, the problem with semaphores is probably due to limitations of the client OS. Current level of performance I have more than satisfied. Thank you again!

Comment by Scott Hernandez (Inactive) [ 30/Aug/12 ]

Ilya, please make sure connectionsForHost is set to the max number of threads which may be active. that error about semaphores says it is too low.

Comment by Jeffrey Yemin [ 30/Aug/12 ]

OK, sounds good. Good luck.

Comment by Ilya Skorik [ 30/Aug/12 ]

https://jira.springsource.org/browse/DATAMONGO-520

Spring-data-mongodb issue created, I will try Morphia

Comment by Ilya Skorik [ 30/Aug/12 ]

This is 100 request by 100 concurent users in "internet" mode (not flood):

Transactions: 973 hits
Availability: 48.48 %
Elapsed time: 24.75 secs
Data transferred: 10.24 MB
Response time: 1.46 secs
Transaction rate: 39.31 trans/sec
Throughput: 0.41 MB/sec
Concurrency: 57.32
Successful transactions: 973
Failed transactions: 1034
Longest transaction: 8.34
Shortest transaction: 0.00

From logs:

11:04:39.615 WARN matrix.webapp.LoginForm - Time for 2725 object is 3201ms
11:04:39.655 WARN matrix.webapp.LoginForm - Time for 2725 object is 713ms
11:04:39.663 WARN matrix.webapp.LoginForm - Time for 2725 object is 1616ms
11:04:39.666 WARN matrix.webapp.LoginForm - Time for 2725 object is 719ms
11:04:39.674 WARN matrix.webapp.LoginForm - Time for 2725 object is 315ms
11:04:39.685 WARN matrix.webapp.LoginForm - Time for 2725 object is 642ms
11:04:39.702 WARN matrix.webapp.LoginForm - Time for 2725 object is 1270ms
11:04:39.818 WARN matrix.webapp.LoginForm - Time for 2725 object is 3203ms
11:04:39.821 WARN matrix.webapp.LoginForm - Time for 2725 object is 836ms
11:04:39.832 WARN matrix.webapp.LoginForm - Time for 2725 object is 596ms
11:04:39.851 WARN matrix.webapp.LoginForm - Time for 2725 object is 342ms
11:04:39.859 WARN matrix.webapp.LoginForm - Time for 2725 object is 1165ms
11:04:39.871 WARN matrix.webapp.LoginForm - Time for 2725 object is 4568ms
11:04:39.873 WARN matrix.webapp.LoginForm - Time for 2725 object is 3667ms
11:04:39.877 WARN matrix.webapp.LoginForm - Time for 2725 object is 2038ms
11:04:39.963 WARN matrix.webapp.LoginForm - Time for 2725 object is 2568ms
11:04:39.970 WARN matrix.webapp.LoginForm - Time for 2725 object is 332ms
11:04:40.046 WARN matrix.webapp.LoginForm - Time for 2725 object is 2593ms
11:04:40.051 WARN matrix.webapp.LoginForm - Time for 2725 object is 668ms
11:04:40.055 WARN matrix.webapp.LoginForm - Time for 2725 object is 2468ms

All errors (>50%) is a 500 error with "Out of semaphores to get db connection".
Can this be a constraint OS or hardware?

Comment by Ilya Skorik [ 30/Aug/12 ]

Without Spring-Datat the result is greatly improved, probably a problem with a single request is in the Spring Data code. But there were other interesting questions.

This is a log of 100 queries with 1 concurrent user:

10:42:22.456 WARN matrix.webapp.LoginForm - Time for 2725 object is 6ms
10:42:22.466 WARN matrix.webapp.LoginForm - Time for 2725 object is 7ms
10:42:22.476 WARN matrix.webapp.LoginForm - Time for 2725 object is 6ms
10:42:22.486 WARN matrix.webapp.LoginForm - Time for 2725 object is 6ms
10:42:22.496 WARN matrix.webapp.LoginForm - Time for 2725 object is 7ms
10:42:22.511 WARN matrix.webapp.LoginForm - Time for 2725 object is 10ms
10:42:22.532 WARN matrix.webapp.LoginForm - Time for 2725 object is 17ms
10:42:22.542 WARN matrix.webapp.LoginForm - Time for 2725 object is 6ms
10:42:22.553 WARN matrix.webapp.LoginForm - Time for 2725 object is 8ms
10:42:22.569 WARN matrix.webapp.LoginForm - Time for 2725 object is 9ms

This is a log of 10 queries with 10 concurrent user:

10:46:50.571 WARN matrix.webapp.LoginForm - Time for 2725 object is 70ms
10:46:50.666 WARN matrix.webapp.LoginForm - Time for 2725 object is 164ms
10:46:50.666 WARN matrix.webapp.LoginForm - Time for 2725 object is 165ms
10:46:50.670 WARN matrix.webapp.LoginForm - Time for 2725 object is 168ms
10:46:50.672 WARN matrix.webapp.LoginForm - Time for 2725 object is 170ms
10:46:50.677 WARN matrix.webapp.LoginForm - Time for 2725 object is 173ms
10:46:50.681 WARN matrix.webapp.LoginForm - Time for 2725 object is 168ms
10:46:50.682 WARN matrix.webapp.LoginForm - Time for 2725 object is 169ms
10:46:50.682 WARN matrix.webapp.LoginForm - Time for 2725 object is 170ms
10:46:50.723 WARN matrix.webapp.LoginForm - Time for 2725 object is 166ms

This is a log of 10 queries with 50 concurrent user:

10:47:47.992 WARN matrix.webapp.LoginForm - Time for 2725 object is 763ms
10:47:48.009 WARN matrix.webapp.LoginForm - Time for 2725 object is 309ms
10:47:48.029 WARN matrix.webapp.LoginForm - Time for 2725 object is 525ms
10:47:48.061 WARN matrix.webapp.LoginForm - Time for 2725 object is 251ms
10:47:48.104 WARN matrix.webapp.LoginForm - Time for 2725 object is 205ms
10:47:48.106 WARN matrix.webapp.LoginForm - Time for 2725 object is 352ms
10:47:48.111 WARN matrix.webapp.LoginForm - Time for 2725 object is 170ms
10:47:48.124 WARN matrix.webapp.LoginForm - Time for 2725 object is 333ms
10:47:48.126 WARN matrix.webapp.LoginForm - Time for 2725 object is 227ms
10:47:48.137 WARN matrix.webapp.LoginForm - Time for 2725 object is 161ms

This is a log of 10 queries with 100 concurrent user:

0:49:12.875 WARN matrix.webapp.LoginForm - Time for 2725 object is 1596ms
10:49:12.894 WARN matrix.webapp.LoginForm - Time for 2725 object is 1289ms
10:49:12.904 WARN matrix.webapp.LoginForm - Time for 2725 object is 1355ms
10:49:12.906 WARN matrix.webapp.LoginForm - Time for 2725 object is 1566ms
10:49:12.976 WARN matrix.webapp.LoginForm - Time for 2725 object is 2000ms
10:49:13.006 WARN matrix.webapp.LoginForm - Time for 2725 object is 3294ms
10:49:13.027 WARN matrix.webapp.LoginForm - Time for 2725 object is 2209ms
10:49:13.038 WARN matrix.webapp.LoginForm - Time for 2725 object is 746ms
10:49:13.082 WARN matrix.webapp.LoginForm - Time for 2725 object is 713ms
10:49:13.088 WARN matrix.webapp.LoginForm - Time for 2725 object is 1761ms

And there is problems with stability. There are many (40-50%) error "Out of semaphores to get db connection"

It can be seen that with the increasing competitive connections, query speed degrades linearly and there are errors connecting to the database.

Question, this property MongoDB or am I wrong to configure a connection to a database?

Comment by Ilya Skorik [ 30/Aug/12 ]

Test controller configuration

Comment by Ilya Skorik [ 30/Aug/12 ]

Mongo Object configuration

Comment by Jeffrey Yemin [ 30/Aug/12 ]

Just to rule out some unknowns:

1. Perform measurements using System.nanoTime instead of Calendar. More accurate for benchmarking.
2. Use the raw java driver instead of Spring Data MongoDB

Comment by Ilya Skorik [ 29/Aug/12 ]

I tested the old applications, generally on my computer Java Web applications work in two to four times more productive than their analogs in PHP. Until then, not to begin to use the Mongo Java Driver. I can not understand what I am wrong and how to fix it.

Comment by Ilya Skorik [ 29/Aug/12 ]

Same computer and database, php:

  • PHP Internet mode

$siege http://localhost:8080/mongotest.php -r 100 -c 10 -i

Transactions: 1000 hits
Availability: 100.00 %
Elapsed time: 55.92 secs
Data transferred: 0.03 MB
Response time: 0.02 secs
Transaction rate: 17.88 trans/sec
Throughput: 0.00 MB/sec
Concurrency: 0.29
Successful transactions: 1000
Failed transactions: 0
Longest transaction: 0.13
Shortest transaction: 0.01

  • PHP Flood mode

$siege http://localhost:8080/mongotest.php -r 100 -c 10 -b

Transactions: 1000 hits
Availability: 100.00 %
Elapsed time: 16.21 secs
Data transferred: 0.03 MB
Response time: 0.16 secs
Transaction rate: 61.69 trans/sec
Throughput: 0.00 MB/sec
Concurrency: 9.96
Successful transactions: 1000
Failed transactions: 0
Longest transaction: 0.27
Shortest transaction: 0.04

  • JAVA - internet mode

$siege http://localhost:8181/zr-matrix/test/1 -r 100 -c 10 -i

Transactions: 1000 hits
Availability: 100.00 %
Elapsed time: 64.90 secs
Data transferred: 0.00 MB
Response time: 0.10 secs
Transaction rate: 15.41 trans/sec
Throughput: 0.00 MB/sec
Concurrency: 1.58
Successful transactions: 1000
Failed transactions: 0
Longest transaction: 0.54
Shortest transaction: 0.05

  • Java - flood mode

$siege http://localhost:8181/zr-matrix/test/1 -r 100 -c 10 -b

Transactions: 1000 hits
Availability: 100.00 %
Elapsed time: 51.85 secs
Data transferred: 0.00 MB
Response time: 0.51 secs
Transaction rate: 19.29 trans/sec
Throughput: 0.00 MB/sec
Concurrency: 9.89
Successful transactions: 1000
Failed transactions: 0
Longest transaction: 1.05
Shortest transaction: 0.06

Comment by Ilya Skorik [ 29/Aug/12 ]

Without a query to the Mongo web application handles something about 1200 requests per second with 0,07 ms per request

Comment by Ilya Skorik [ 29/Aug/12 ]

done.
Transactions: 1000 hits
Availability: 100.00 %
Elapsed time: 74.59 secs
Data transferred: 0.00 MB
Response time: 0.15 secs
Transaction rate: 13.41 trans/sec
Throughput: 0.00 MB/sec
Concurrency: 2.05
Successful transactions: 1000
Failed transactions: 0
Longest transaction: 1.04
Shortest transaction: 0.05

The results have not changed much.

I run the compiled application from war archive in a separate tomcat instance, outside the development environment. Computer - Macbook Pro 13, 2011, with Corei5 and 8Gb Ram, SSD drive. OSX 10.8.1

Comment by Ilya Skorik [ 29/Aug/12 ]

Without sorting

Comment by Ilya Skorik [ 29/Aug/12 ]

Without sorting

Comment by Jeffrey Yemin [ 29/Aug/12 ]

The PHP and Java apps are performing different queries. The Java app is sorting on a field, and the PHP app is not. Can you make them consistent and retest?

Comment by Ilya Skorik [ 29/Aug/12 ]

Jeff, I've tested the application with 1000 transactions, they all are slow. If the problem is in the sockets, what to do, that would increase the speed of five to ten times?

Comment by Ilya Skorik [ 29/Aug/12 ]

This is Siege log

$siege http://localhost:8181/zr-matrix/test/1 -r 100 -c 10 -i

Transactions: 1000 hits
Availability: 100.00 %
Elapsed time: 90.01 secs
Data transferred: 0.00 MB
Response time: 0.40 secs
Transaction rate: 11.11 trans/sec
Throughput: 0.00 MB/sec
Concurrency: 4.48
Successful transactions: 1000
Failed transactions: 0
Longest transaction: 1.74
Shortest transaction: 0.05

Simple controller, a simple test. No operations on the data or complex view.
Look in the matrix-app.log, I do not understand why so much jumping query time value in this test. And why are they so big. php script on this test gives significantly more attractive results.

It is normal for Java or I something wrong?

Comment by Jeffrey Yemin [ 29/Aug/12 ]

The Mongo instance manages a pool of sockets, which are created lazily, so the first time a thread invokes an operation that needs to interact with the server, the socket will be created and opened, and this operation will be slower as a result.

One thing you could try is warming your server before it becomes available for use, thus forcing socket creation.

Comment by Ilya Skorik [ 29/Aug/12 ]

This is spring-mvc controller

Comment by Ilya Skorik [ 29/Aug/12 ]

Query time log from app

Comment by Ilya Skorik [ 29/Aug/12 ]

I'm using spring-mvc and spring-data-mongodb, did everything according to official instructions. According to the logs, the Mongo object is created only once.

But each request takes 250-300ms, when a similar php request - 60ms. I do not know how to explain it, and how to fix it.

Do you have any ideas?

Comment by Jeffrey Yemin [ 29/Aug/12 ]

It's likely because the Java driver lazily opens sockets for each thread on first use of mongo

Generated at Thu Feb 08 08:52:43 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.