2 Hours to start

[rafael-leo-almeida]

Hi, I'm trying to use restheart to enable access to our MongoDB DataRepository, as an read-only way to consumer our. But the restheart get 2hours to start.

18:05:42.657 [main] INFO  org.restheart.Bootstrapper - MongoDB connection pool initialized
21:01:11.064 [main] INFO  org.restheart.Bootstrapper - Token based authentication enabled with token TTL 15 minutes

It's normal?

[ujibang]

Not at all, RESTHeart is very lightweight and usually takes less than a second to startup!

Can you provide more info (OS, hardware specs , java version, mongodb version)

Also, looking at the log messages, do you note any step that requires lot of time to complete? Or all steps are slow?

[rafael-leo-almeida]

In this case only restheart log I did not get any log between this almost 2 hours. And in mongodb logs i got hundreds of the same command.

I COMMAND  [conn318] command admin.$cmd command: listDatabases { listDatabases: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:3390 locks:{ Global: { acquireCount: { r: 116 } }, Database: { acquireCount: { r: 58 } } } 784ms

System info: RestHeart: 0.10.4 MongoDB 3.0.5 (58 DBs, 8399TotalCollections)

db.serverBuildInfo()
{
    "version" : "3.0.5",
    "gitVersion" : "8bc4ae20708dbb493cb09338d9e7be6698e4a3a3",
    "OpenSSLVersion" : "OpenSSL 1.0.0-fips 29 Mar 2010",
    "sysInfo" : "Linux ip-10-230-137-3 3.4.43-43.43.amzn1.x86_64 #1 SMP Mon May 6 18:04:41 UTC 2013 x86_64 BOOST_LIB_VERSION=1_49",
    "versionArray" : [
        3,
        0,
        5,
        0
    ],
    "loaderFlags" : "",
    "compilerFlags" : "-Wnon-virtual-dtor -Woverloaded-virtual -std=c++11 -fPIC -fno-strict-aliasing -ggdb -pthread -Wall -Wsign-compare -Wno-unknown-pragmas -Winvalid-pch -pipe -Werror -O3 -Wno-unused-local-typedefs -Wno-unused-function -Wno-deprecated-declarations -Wno-unused-but-set-variable -Wno-missing-braces -fno-builtin-memcmp -std=c99",
    "allocator" : "tcmalloc",
    "javascriptEngine" : "V8",
    "bits" : 64,
    "debug" : false,
    "maxBsonObjectSize" : 16777216,
    "ok" : 1
}

SO: Amazon Linux Java: openjdk version "1.8.0_51" OpenJDK Runtime Environment (build 1.8.0_51-b16) OpenJDK 64-Bit Server VM (build 25.51-b03, mixed mode)

[ujibang]

Please set the log level to DEBUG in yml config file, and restart it.

Paste the log messages.

RESTHeart scans existing dbs and collections during startup to add some default properties if not existing such as the etag (this can happen if the db/collection has not be created via RESTHeart itself)

I suspect that in your case (58 dbs and 8400 collections) this might take too long.

If we confirm this is the case we can add a parameter to skip this operation.

Look forward for your feedback

[rafael-leo-almeida]

First Time I see the log of creating properties.. But on next time just stop on

09:10:12.081 [main] INFO  org.restheart.Bootstrapper - MongoDB connection pool initialized

I will enable debug and start again...

[ujibang]

And how log did it take the first time to add the properties (for how long have you noticed those log messages being printed)?

[rafael-leo-almeida]

On first time this took the same 2 hours.

Even with log-level DEBUG the log stop on MongoDB connection pool initialized.

09:10:11.561 [main] INFO  org.restheart.Bootstrapper - Starting RESTHeart ********************************************
09:10:11.620 [main] INFO  org.restheart.Bootstrapper - Creating pid file /var/run/restheart.pid
09:10:11.841 [main] INFO  org.restheart.Bootstrapper - RESTHeart version 0.10.4
09:10:12.080 [main] INFO  org.restheart.Bootstrapper - Initializing MongoDB connection pool to 10.5.4.4:27017 
09:10:12.081 [main] INFO  org.restheart.Bootstrapper - MongoDB connection pool initialized
10:53:59.940 [main] INFO  org.restheart.Bootstrapper - Forking RESTHeart ********************************************
10:53:59.999 [main] DEBUG org.restheart.Configuration - paramenter https-listener set to true
10:54:00.000 [main] DEBUG org.restheart.Configuration - paramenter https-port set to 443
10:54:00.000 [main] DEBUG org.restheart.Configuration - paramenter https-host set to 0.0.0.0
10:54:00.000 [main] DEBUG org.restheart.Configuration - paramenter http-listener set to true
10:54:00.000 [main] DEBUG org.restheart.Configuration - paramenter http-port set to 80
10:54:00.000 [main] DEBUG org.restheart.Configuration - paramenter http-host set to 0.0.0.0
10:54:00.000 [main] DEBUG org.restheart.Configuration - paramenter ajp-listener set to false
10:54:00.000 [main] DEBUG org.restheart.Configuration - paramenter ajp-port set to 8009
10:54:00.000 [main] DEBUG org.restheart.Configuration - paramenter ajp-host set to 0.0.0.0
10:54:00.000 [main] DEBUG org.restheart.Configuration - paramenter use-embedded-keystore set to true
10:54:00.000 [main] DEBUG org.restheart.Configuration - parameters group mongo-credentials not specified in the configuration file, using its default value null
10:54:00.001 [main] DEBUG org.restheart.Configuration - paramenter implementation-class set to org.restheart.security.impl.SimpleFileIdentityManager
10:54:00.001 [main] DEBUG org.restheart.Configuration - paramenter implementation-class set to org.restheart.security.impl.SimpleAccessManager
10:54:00.001 [main] DEBUG org.restheart.Configuration - paramenter log-file-path set to /var/log/restheart/restheart.log
10:54:00.001 [main] DEBUG org.restheart.Configuration - paramenter log-level set to DEBUG
10:54:00.001 [main] DEBUG org.restheart.Configuration - paramenter enable-log-console set to true
10:54:00.001 [main] DEBUG org.restheart.Configuration - paramenter enable-log-file set to true
10:54:00.001 [main] DEBUG org.restheart.Configuration - paramenter requests-limit set to 1000
10:54:00.001 [main] DEBUG org.restheart.Configuration - paramenter local-cache-enabled set to false
10:54:00.009 [main] DEBUG org.restheart.Configuration - paramenter local-cache-ttl set to 1000
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter io-threads set to 2
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter worker-threads set to 8
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter buffer-size set to 16384
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter buffers-per-region set to 20
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter direct-buffers set to true
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter force-gzip-encoding set to true
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter eager-cursor-allocation-pool-size set to 100
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter eager-cursor-allocation-linear-slice-width set to 1000
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter eager-cursor-allocation-linear-slice-delta set to 100
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter eager-cursor-allocation-linear-slice-heights set to [4, 2, 1]
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter eager-cursor-allocation-random-slice-min-width set to 1000
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter eager-cursor-allocation-random-max-cursors set to 20
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter auth-token-enabled set to true
10:54:00.010 [main] DEBUG org.restheart.Configuration - paramenter auth-token-ttl set to 15
10:54:00.010 [main] INFO  org.restheart.Bootstrapper - pid file /var/run/restheart.pid
10:54:00.228 [main] INFO  org.restheart.Bootstrapper - RESTHeart version 0.10.4
10:54:00.469 [main] INFO  org.restheart.Bootstrapper - Initializing MongoDB connection pool to  X.X.X.X:27017 
10:54:00.469 [main] INFO  org.restheart.Bootstrapper - MongoDB connection pool initialized

[rafael-leo-almeida]

Seems it stop on

Bootstrapper.java (319)

new PropsFixer().fixAllMissingProps();

[rafael-leo-almeida]

Is there a way to define one or a list of dbs to be used by restheart?

[ujibang]

The list of dbs or collections to use are defined by the mongo-mount configuration option.

Can you try to comment out that code line (Bottstrapper:319) and rebuild (this will slip the scan, that you have already performed anyway)

If you confirm this is the issue, I'll add an option to skip this phase in the configuration file.

Thanks

[rafael-leo-almeida]

Ok, i will do that, and forward the result here, soon as possible.

[rafael-leo-almeida]

Hi, I'd testing with code line (Bottstrapper:319) commented and works as well. I'd test too with a resource defined and (Bottstrapper:319) uncommented, i could see that even a unique resource defined the fixAllMissingProps() in PropsFixer, sweeps every dbs to check if _properties exists.

[ujibang]

Well done!

I'll add an option to skip the properties fixing altogether and also limit it to the mounted resources anyway.

I'll also try to speed up the operation.

I'm in vacation now so I do it as soon as I get back. Should close it in couple of weeks.

Thanks for pointing out this issue

[rafael-leo-almeida]

Great. Thanx!!!!

[ujibang]

Took this issue, more info at https://softinstigate.atlassian.net/browse/RH-90

[ujibang]

fixed in develop branch.

will be part of release 0.11

thanks for reporting this.