Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

#balance(): takes more than 1min, 8hr already #436

Closed
yegor256 opened this issue Oct 31, 2013 · 5 comments
Closed

#balance(): takes more than 1min, 8hr already #436

yegor256 opened this issue Oct 31, 2013 · 5 comments
Labels
bug

Comments

@yegor256
Copy link
Owner

PostgreSQL interaction takes too much time in unit testing, for example:

INFO [2;37mDEBUGm] jcabi-loggable com.rultor.users.pgsql.PgAccount: #balance(): thread main/TIMED_WAITING stacktrace: sun.misc.Unsafe#park[-2], java.util.concurrent.locks.LockSupport#parkNanos[226], java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject#awaitNanos[2082], java.util.concurrent.LinkedBlockingQueue#poll[467], com.jolbox.bonecp.DefaultConnectionStrategy#getConnectionInternal[82], com.jolbox.bonecp.AbstractConnectionStrategy#getConnection[90], com.jolbox.bonecp.BoneCP#getConnection[553], com.jolbox.bonecp.BoneCPDataSource#getConnection[131], com.jcabi.jdbc.JdbcSession#connect[432], com.jcabi.jdbc.JdbcSession#run[393], com.jcabi.jdbc.JdbcSession#select_aroundBody14[361], com.jcabi.jdbc.JdbcSession$AjcClosure15#run[1], org.aspectj.runtime.reflect.JoinPointImpl#proceed[149], com.jcabi.aspects.aj.MethodLogger#wrap[204], com.jcabi.aspects.aj.MethodLogger#ajc$inlineAccessMethod$com_jcabi_aspects_aj_MethodLogger$com_jcabi_aspects_aj_MethodLogger$wrap[1], com.jcabi.aspects.aj.MethodLogger#wrapClass[132], com.jcabi.jdbc.JdbcSession#select[361], com.rultor.users.pgsql.PgAccount#balance_aroundBody0[86], com.rultor.users.pgsql.PgAccount$AjcClosure1#run[1], org.aspectj.runtime.reflect.JoinPointImpl#proceed[149], com.jcabi.aspects.aj.MethodLogger#wrap[204], com.jcabi.aspects.aj.MethodLogger#ajc$inlineAccessMethod$com_jcabi_aspects_aj_MethodLogger$com_jcabi_aspects_aj_MethodLogger$wrap[1], com.jcabi.aspects.aj.MethodLogger#wrapClass[132], com.rultor.users.pgsql.PgAccount#balance_aroundBody2[86], com.rultor.users.pgsql.PgAccount$AjcClosure3#run[1], org.aspectj.runtime.reflect.JoinPointImpl#proceed[149], com.jcabi.aspects.aj.MethodCacher$Tunnel#through[277], com.jcabi.aspects.aj.MethodCacher#cache[126], com.rultor.users.pgsql.PgAccount#balance[86], com.rultor.users.pgsql.PgAccountITCase#account[146], com.rultor.users.pgsql.PgAccountITCase#fundsItself[94], sun.reflect.NativeMethodAccessorImpl#invoke0[-2], sun.reflect.NativeMethodAccessorImpl#invoke[57], sun.reflect.DelegatingMethodAccessorImpl#invoke[43], java.lang.reflect.Method#invoke[606], org.junit.runners.model.FrameworkMethod$1#runReflectiveCall[47], org.junit.internal.runners.model.ReflectiveCallable#run[12], org.junit.runners.model.FrameworkMethod#invokeExplosively[44], org.junit.internal.runners.statements.InvokeMethod#evaluate[17], org.junit.runners.ParentRunner#runLeaf[271], org.junit.runners.BlockJUnit4ClassRunner#runChild[70], org.junit.runners.BlockJUnit4ClassRunner#runChild[50], org.junit.runners.ParentRunner$3#run[238], org.junit.runners.ParentRunner$1#schedule[63], org.junit.runners.ParentRunner#runChildren[236], org.junit.runners.ParentRunner#access$000[53], org.junit.runners.ParentRunner$2#evaluate[229], org.junit.runners.ParentRunner#run[309], org.junit.runners.Suite#runChild[127], org.junit.runners.Suite#runChild[26], org.junit.runners.ParentRunner$3#run[238], org.junit.runners.ParentRunner$1#schedule[63], org.junit.runners.ParentRunner#runChildren[236], org.junit.runners.ParentRunner#access$000[53], org.junit.runners.ParentRunner$2#evaluate[229], org.junit.runners.ParentRunner#run[309], org.junit.runner.JUnitCore#run[160], org.junit.runner.JUnitCore#run[138], org.apache.maven.surefire.junitcore.JUnitCoreWrapper#createRequestAndRun[141], org.apache.maven.surefire.junitcore.JUnitCoreWrapper#executeEager[114], org.apache.maven.surefire.junitcore.JUnitCoreWrapper#execute[86], org.apache.maven.surefire.junitcore.JUnitCoreProvider#invoke[134], sun.reflect.NativeMethodAccessorImpl#invoke0[-2], sun.reflect.NativeMethodAccessorImpl#invoke[57], sun.reflect.DelegatingMethodAccessorImpl#invoke[43], java.lang.reflect.Method#invoke[606], org.apache.maven.surefire.util.ReflectionUtils#invokeMethodWithArray2[208], org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy#invoke[156], org.apache.maven.surefire.booter.ProviderFactory#invokeProvider[82], org.apache.maven.plugin.surefire.InPluginVMSurefireStarter#runSuitesInProcess[82], org.apache.maven.plugin.surefire.AbstractSurefireMojo#executeProvider[942], org.apache.maven.plugin.surefire.AbstractSurefireMojo#executeAfterPreconditionsChecked[822], org.apache.maven.plugin.surefire.AbstractSurefireMojo#execute[720], org.apache.maven.plugin.DefaultBuildPluginManager#executeMojo[101], org.apache.maven.lifecycle.internal.MojoExecutor#execute[209], org.apache.maven.lifecycle.internal.MojoExecutor#execute[153], org.apache.maven.lifecycle.internal.MojoExecutor#execute[145], org.apache.maven.lifecycle.internal.LifecycleModuleBuilder#buildProject[84], org.apache.maven.lifecycle.internal.LifecycleModuleBuilder#buildProject[59], org.apache.maven.lifecycle.internal.LifecycleStarter#singleThreadedBuild[183], org.apache.maven.lifecycle.internal.LifecycleStarter#execute[161], org.apache.maven.DefaultMaven#doExecute[320], org.apache.maven.DefaultMaven#execute[156], org.apache.maven.cli.MavenCli#execute[537], org.apache.maven.cli.MavenCli#doMain[196], org.apache.maven.cli.MavenCli#main[141], sun.reflect.NativeMethodAccessorImpl#invoke0[-2], sun.reflect.NativeMethodAccessorImpl#invoke[57], sun.reflect.DelegatingMethodAccessorImpl#invoke[43], java.lang.reflect.Method#invoke[606], org.codehaus.plexus.classworlds.launcher.Launcher#launchEnhanced[290], org.codehaus.plexus.classworlds.launcher.Launcher#launch[230], org.codehaus.plexus.classworlds.launcher.Launcher#mainWithExitCode[409], org.codehaus.plexus.classworlds.launcher.Launcher#main[352]
INFO Thu Oct 31 17:50:57.434 [DataFileSync] flushing mmaps took 0ms for 4 files
INFO [mongod output] Thu Oct 31 17:50:57.752 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:151 nreturned:0 reslen:20 0ms
INFO [mongod output] Thu Oct 31 17:50:57.752 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:42 nreturned:0 reslen:20 0ms
INFO [mongod output] [0;33mWARNm] jcabi-loggable com.jcabi.jdbc.JdbcSession: #select('SingleHandler(type=class java.lang.Long, silently=false)'): takes more than 1min, 8hr already, thread=main/TIMED_WAITING
INFO [0;33mWARNm] jcabi-loggable com.rultor.users.pgsql.PgAccount: #balance(): takes more than 1min, 8hr already, thread=main/TIMED_WAITING
INFO [2;37mDEBUGm] jcabi-loggable com.rultor.users.pgsql.PgAccount: #balance(): thread main/TIMED_WAITING stacktrace: sun.misc.Unsafe#park[-2], java.util.concurrent.locks.LockSupport#parkNanos[226], java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject#awaitNanos[2082], java.util.concurrent.LinkedBlockingQueue#poll[467], com.jolbox.bonecp.DefaultConnectionStrategy#getConnectionInternal[82], com.jolbox.bonecp.AbstractConnectionStrategy#getConnection[90], com.jolbox.bonecp.BoneCP#getConnection[553], com.jolbox.bonecp.BoneCPDataSource#getConnection[131], com.jcabi.jdbc.JdbcSession#connect[432], com.jcabi.jdbc.JdbcSession#run[393], com.jcabi.jdbc.JdbcSession#select_aroundBody14[361], com.jcabi.jdbc.JdbcSession$AjcClosure15#run[1], org.aspectj.runtime.reflect.JoinPointImpl#proceed[149], com.jcabi.aspects.aj.MethodLogger#wrap[204], com.jcabi.aspects.aj.MethodLogger#ajc$inlineAccessMethod$com_jcabi_aspects_aj_MethodLogger$com_jcabi_aspects_aj_MethodLogger$wrap[1], com.jcabi.aspects.aj.MethodLogger#wrapClass[132], com.jcabi.jdbc.JdbcSession#select[361], com.rultor.users.pgsql.PgAccount#balance_aroundBody0[86], com.rultor.users.pgsql.PgAccount$AjcClosure1#run[1], org.aspectj.runtime.reflect.JoinPointImpl#proceed[149], com.jcabi.aspects.aj.MethodLogger#wrap[204], com.jcabi.aspects.aj.MethodLogger#ajc$inlineAccessMethod$com_jcabi_aspects_aj_MethodLogger$com_jcabi_aspects_aj_MethodLogger$wrap[1], com.jcabi.aspects.aj.MethodLogger#wrapClass[132], com.rultor.users.pgsql.PgAccount#balance_aroundBody2[86], com.rultor.users.pgsql.PgAccount$AjcClosure3#run[1], org.aspectj.runtime.reflect.JoinPointImpl#proceed[149], com.jcabi.aspects.aj.MethodCacher$Tunnel#through[277], com.jcabi.aspects.aj.MethodCacher#cache[126], com.rultor.users.pgsql.PgAccount#balance[86], com.rultor.users.pgsql.PgAccountITCase#account[146], com.rultor.users.pgsql.PgAccountITCase#fundsItself[94], sun.reflect.NativeMethodAccessorImpl#invoke0[-2], sun.reflect.NativeMethodAccessorImpl#invoke[57], sun.reflect.DelegatingMethodAccessorImpl#invoke[43], java.lang.reflect.Method#invoke[606], org.junit.runners.model.FrameworkMethod$1#runReflectiveCall[47], org.junit.internal.runners.model.ReflectiveCallable#run[12], org.junit.runners.model.FrameworkMethod#invokeExplosively[44], org.junit.internal.runners.statements.InvokeMethod#evaluate[17], org.junit.runners.ParentRunner#runLeaf[271], org.junit.runners.BlockJUnit4ClassRunner#runChild[70], org.junit.runners.BlockJUnit4ClassRunner#runChild[50], org.junit.runners.ParentRunner$3#run[238], org.junit.runners.ParentRunner$1#schedule[63], org.junit.runners.ParentRunner#runChildren[236], org.junit.runners.ParentRunner#access$000[53], org.junit.runners.ParentRunner$2#evaluate[229], org.junit.runners.ParentRunner#run[309], org.junit.runners.Suite#runChild[127], org.junit.runners.Suite#runChild[26], org.junit.runners.ParentRunner$3#run[238], org.junit.runners.ParentRunner$1#schedule[63], org.junit.runners.ParentRunner#runChildren[236], org.junit.runners.ParentRunner#access$000[53], org.junit.runners.ParentRunner$2#evaluate[229], org.junit.runners.ParentRunner#run[309], org.junit.runner.JUnitCore#run[160], org.junit.runner.JUnitCore#run[138], org.apache.maven.surefire.junitcore.JUnitCoreWrapper#createRequestAndRun[141], org.apache.maven.surefire.junitcore.JUnitCoreWrapper#executeEager[114], org.apache.maven.surefire.junitcore.JUnitCoreWrapper#execute[86], org.apache.maven.surefire.junitcore.JUnitCoreProvider#invoke[134], sun.reflect.NativeMethodAccessorImpl#invoke0[-2], sun.reflect.NativeMethodAccessorImpl#invoke[57], sun.reflect.DelegatingMethodAccessorImpl#invoke[43], java.lang.reflect.Method#invoke[606], org.apache.maven.surefire.util.ReflectionUtils#invokeMethodWithArray2[208], org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy#invoke[156], org.apache.maven.surefire.booter.ProviderFactory#invokeProvider[82], org.apache.maven.plugin.surefire.InPluginVMSurefireStarter#runSuitesInProcess[82], org.apache.maven.plugin.surefire.AbstractSurefireMojo#executeProvider[942], org.apache.maven.plugin.surefire.AbstractSurefireMojo#executeAfterPreconditionsChecked[822], org.apache.maven.plugin.surefire.AbstractSurefireMojo#execute[720], org.apache.maven.plugin.DefaultBuildPluginManager#executeMojo[101], org.apache.maven.lifecycle.internal.MojoExecutor#execute[209], org.apache.maven.lifecycle.internal.MojoExecutor#execute[153], org.apache.maven.lifecycle.internal.MojoExecutor#execute[145], org.apache.maven.lifecycle.internal.LifecycleModuleBuilder#buildProject[84], org.apache.maven.lifecycle.internal.LifecycleModuleBuilder#buildProject[59], org.apache.maven.lifecycle.internal.LifecycleStarter#singleThreadedBuild[183], org.apache.maven.lifecycle.internal.LifecycleStarter#execute[161], org.apache.maven.DefaultMaven#doExecute[320], org.apache.maven.DefaultMaven#execute[156], org.apache.maven.cli.MavenCli#execute[537], org.apache.maven.cli.MavenCli#doMain[196], org.apache.maven.cli.MavenCli#main[141], sun.reflect.NativeMethodAccessorImpl#invoke0[-2], sun.reflect.NativeMethodAccessorImpl#invoke[57], sun.reflect.DelegatingMethodAccessorImpl#invoke[43], java.lang.reflect.Method#invoke[606], org.codehaus.plexus.classworlds.launcher.Launcher#launchEnhanced[290], org.codehaus.plexus.classworlds.launcher.Launcher#launch[230], org.codehaus.plexus.classworlds.launcher.Launcher#mainWithExitCode[409], org.codehaus.plexus.classworlds.launcher.Launcher#main[352]
INFO Thu Oct 31 17:51:57.434 [DataFileSync] flushing mmaps took 0ms for 4 files
INFO [mongod output] Thu Oct 31 17:51:57.752 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:164 nreturned:0 reslen:20 0ms
INFO [mongod output] Thu Oct 31 17:51:57.752 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:38 nreturned:0 reslen:20 0ms
INFO [mongod output] [0;33mWARNm] jcabi-loggable com.jcabi.jdbc.JdbcSession: #select('SingleHandler(type=class java.lang.Long, silently=false)'): takes more than 1min, 8hr already, thread=main/TIMED_WAITING
INFO [0;33mWARNm] jcabi-loggable com.rultor.users.pgsql.PgAccount: #balance(): takes more than 1min, 8hr already, thread=main/TIMED_WAITING
@yegor256 yegor256 mentioned this issue Nov 1, 2013
Merged
@yegor256
Copy link
Owner Author

yegor256 commented Nov 1, 2013

@krzyk can you help? Really strange error, appeared yesterday

@yegor256
Copy link
Owner Author

yegor256 commented Nov 1, 2013

This is what I see in log:

 36:18 INFO [2;37mDEBUGm] main com.rultor.snapshot.XSLT: #dom(): '[#document: null]' in 78ms
 36:18 INFO [2;37mDEBUGm] main com.rultor.spi.Tag$Simple: #label(): 'foo' in 27µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.spi.Tag$Simple: #level(): INFO in 41µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.spi.Tag$Simple: #attributes(): '' in 26µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.spi.Tag$Simple: #markdown(): '' in 26µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoTag: #label(): 'foo' in 37µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoTag: #level(): INFO in 44µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoTag: #markdown(): '' in 43µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoTag: #asObject(): '{ \"label\" : \"foo\" , \"level\" : \"INFO\" , \"attributes\" : { } , \"markdown\" : \"\"}' in 2ms
 36:18 INFO Thu Oct 31 18:41:05.595 [conn1]   running multiple plans
 36:18 INFO [mongod output] Thu Oct 31 18:41:05.595 [conn1] update test.stands query: { _id: ObjectId('5272a44108c5efff22909268'), coordinates: { owner: "urn:test:1", rule: "fbYEQiJCNB", scheduled: "2013-10-31T18:41:05Z" }, stand: "avolh", xembly: "" } update: { stand: "avolh", updated: "2013-10-31T18:41:05Z", xembly: "2 ADD 'tags'; ADD 'tag'; ADD 'label'; SET 'foo';
 36:18 INFO [mongod output] [2;37mDEBUGm] main com.rultor.users.mongo.MongoStand: #post('2013-10-31T18:41:05Z fbYEQiJCNB urn:test:1', 2, 'ADD 'tags'; ADD 'tag'; ADD 'label'; SET 'foo';'): in 141ms
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.Mongo$Simple: #get(): test from cache (hit #74, 13s old)
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoStand: #name(): 'avolh' in 142µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.spi.Coordinates$Simple: #owner(): urn:test:1 in 18µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.spi.Coordinates$Simple: #rule(): 'fbYEQiJCNB' in 20µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.spi.Coordinates$Simple: #scheduled(): 2013-10-31T18:41:05Z in 19µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoCoords: #owner(): urn:test:1 in 8µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoCoords: #rule(): 'fbYEQiJCNB' in 12µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoCoords: #scheduled(): 2013-10-31T18:41:05Z in 12µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoCoords: #asObject(): '{ \"owner\" : \"urn:test:1\" , \"rule\" : \"fbYEQiJCNB\" , \"scheduled\" : \"2013-10-31T18:41:05Z\"}' in 1ms
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.Mongo$Simple: #get(): test from cache (hit #75, 13s old)
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoStand: #name(): 'avolh' in 82µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.spi.Coordinates$Simple: #owner(): urn:test:1 in 12µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.spi.Coordinates$Simple: #rule(): 'fbYEQiJCNB' in 12µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.spi.Coordinates$Simple: #scheduled(): 2013-10-31T18:41:05Z in 12µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoCoords: #owner(): urn:test:1 in 9µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoCoords: #rule(): 'fbYEQiJCNB' in 12µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoCoords: #scheduled(): 2013-10-31T18:41:05Z in 15µs
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoCoords: #asObject(): '{ \"owner\" : \"urn:test:1\" , \"rule\" : \"fbYEQiJCNB\" , \"scheduled\" : \"2013-10-31T18:41:05Z\"}' in 1ms
 36:18 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoStand: #decode('2 ADD 'tags'; ADD 'tag'; ADD 'label'; SET 'foo';\n1 ADD 'test'; SET 'hello, world!';\n'): 'ADD 'test'; SET 'hello, world!';\nADD 'tags'; ADD 'tag'; ADD 'label'; SET 'foo';' in 76µs
 36:18 INFO ", coordinates: { owner: "urn:test:1", rule: "fbYEQiJCNB", scheduled: "2013-10-31T18:41:05Z" }, tags: [ { label: "foo", level: "INFO", attributes: {}, markdown: "" } ] } nscanned:1 nmoved:1 nupdated:1 keyUpdates:0 locks(micros) w:372 0ms
χemβly 'XPATH "/snapshot"; ADDIF "lines"; SET "6613";'
 40:16 INFO [mongod output] Thu Oct 31 18:41:05.620 [conn1] run command test.$cmd { getlasterror: 1 }
 40:16 INFO [mongod output] Thu Oct 31 18:41:05.620 [conn1] command test.$cmd command: { getlasterror: 1 } ntoreturn:1 keyUpdates:0  reslen:85 0ms
 40:16 INFO [mongod output] Thu Oct 31 18:41:05.626 [conn1] run command test.$cmd { findandmodify: "stands", query: { stand: "avolh", coordinates: { owner: "urn:test:1", rule: "fbYEQiJCNB", scheduled: "2013-10-31T18:41:05Z" } }, fields: { coordinates: 1, stand: 1, tags: 1, xembly: 1 }, update: { $setOnInsert: { xembly: "" } }, new: true, upsert: true }
 40:16 INFO [mongod output] Thu Oct 31 18:41:05.626 [conn1] command test.$cmd command: { findandmodify: "stands", query: { stand: "avolh", coordinates: { owner: "urn:test:1", rule: "fbYEQiJCNB", scheduled: "2013-10-31T18:41:05Z" } }, fields: { coordinates: 1, stand: 1, tags: 1, xembly: 1 }, update: { $setOnInsert: { xembly: "" } }, new: true, upsert: true } update: { $setOnInsert: { xembly: "" } } ntoreturn:1 idhack:1 nupdated:1 fastmod:1 keyUpdates:0 locks(micros) w:218 reslen:371 0ms
 40:16 INFO [mongod output] [2;37mDEBUGm] main com.rultor.snapshot.XSLT: #dom(): '[#document: null]' in 36ms
 40:16 INFO Thu Oct 31 18:41:05.673 [conn1] update test.stands query: { _id: ObjectId('5272a44108c5efff22909268'), stand: "avolh", xembly: "2 ADD 'tags'; ADD 'tag'; ADD 'label'; SET 'foo';
 40:16 INFO [mongod output] ", coordinates: { owner: "urn:test:1", rule: "fbYEQiJCNB", scheduled: "2013-10-31T18:41:05Z" }, tags: [ { label: "foo", level: "INFO", attributes: {}, markdown: "" } ] } update: { stand: "avolh", updated: "2013-10-31T18:41:05Z", xembly: "2 ADD 'tags'; ADD 'tag'; ADD 'label'; SET 'foo';
 40:16 INFO [mongod output] 1 ADD 'test'; SET 'hello, world!';
 40:16 INFO [mongod output] ", coordinates: { owner: "urn:test:1", rule: "fbYEQiJCNB", scheduled: "2013-10-31T18:41:05Z" }, tags: {} } nscanned:1 nupdated:1 keyUpdates:0 locks(micros) w:214 0ms
 40:16 INFO [mongod output] Thu Oct 31 18:41:05.673 [conn1] run command test.$cmd { getlasterror: 1 }
 40:16 INFO [mongod output] Thu Oct 31 18:41:05.673 [conn1] command test.$cmd command: { getlasterror: 1 } ntoreturn:1 keyUpdates:0  reslen:85 0ms
 40:16 INFO [mongod output] [2;37mDEBUGm] main com.rultor.users.mongo.MongoStand: #post('2013-10-31T18:41:05Z fbYEQiJCNB urn:test:1', 1, 'ADD 'test'; SET 'hello, world!';'): in 53ms
 40:16 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoStand: #pulses(): 'MongoPulses(mongo=Mongo.Simple(host=localhost, po..65..tand(name=avolh), optional=Predicate.Any())' in 128µs
 40:16 INFO [2;37mDEBUGm] main com.rultor.users.mongo.Mongo$Simple: #get(): test from cache (hit #76, 13s old)
 40:16 INFO [2;37mDEBUGm] main com.rultor.users.mongo.Predicate$InStand: #query(): '{ \"stand\" : \"avolh\"}' in 12µs
 40:16 INFO [2;37mDEBUGm] main com.rultor.users.mongo.Predicate$Any: #query(): '{ }' in 14µs
 40:16 INFO [2;37mDEBUGm] main com.rultor.users.mongo.Predicate$And: #query(): '{ \"$and\" : [ { \"stand\" : \"avolh\"} , { }]}' in 7ms
 40:16 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoPulses: #iterator(): com.rultor.users.mongo.MongoPulses$2@4eb1e8fb in 13ms
 40:16 INFO Thu Oct 31 18:41:05.689 [conn1] query test.stands query: { $query: { $and: [ { stand: "avolh" }, {} ] }, $orderby: { updated: -1 } } ntoreturn:0 ntoskip:0 nscanned:4 scanAndOrder:1 keyUpdates:0 locks(micros) r:153 nreturned:1 reslen:167 0ms
 40:16 INFO [mongod output] [2;37mDEBUGm] main com.rultor.users.mongo.Mongo$Simple: #get(): test from cache (hit #77, 13s old)
 40:16 INFO Thu Oct 31 18:41:05.690 [conn1] query test.stands query: { _id: ObjectId('5272a44108c5efff22909268') } ntoreturn:1 idhack:1 keyUpdates:0 locks(micros) r:24 reslen:173 0ms
 40:16 INFO [mongod output] [2;37mDEBUGm] main com.rultor.users.mongo.MongoStand: #decode('2 ADD 'tags'; ADD 'tag'; ADD 'label'; SET 'foo';\n1 ADD 'test'; SET 'hello, world!';\n'): 'ADD 'test'; SET 'hello, world!';\nADD 'tags'; ADD 'tag'; ADD 'label'; SET 'foo';' in 65µs
 40:16 INFO [2;37mDEBUGm] main com.rultor.users.mongo.MongoPulse: #xembly(): 'ADD 'test'; SET 'hello, world!';\nADD 'tags'; ADD ..43..ADDIF 'updated';SET '2013-10-31T18:41:05Z';' in 2ms
 40:16 INFO Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 5.619 sec - in com.rultor.users.mongo.MongoStandITCase
 40:16 INFO Running com.rultor.users.AwsStandsITCase
 40:16 INFO [0;37mINFOm] main com.jcabi.dynamo.TableMocker: DynamoDB table 'stands' is ACTIVE
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStands: #create('test-rule-new'): in 100ms
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStands: #get('test-rule-new'): 'AwsStand(item=AwsItem(credentials=us-east-1/AAAAA..503..wner={S: urn:test:7,}, keys=owner, stand))' in 138ms
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStand: #acl(): Spec.Simple(text=com.rultor.acl.Prohibited()) in 189ms
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStand: #acl(): Spec.Simple(text=com.rultor.acl.Prohibited()) cached in 190ms, valid for 5min
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStand: #widgets(): Spec.Simple(text=[]) in 104ms
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStand: #widgets(): Spec.Simple(text=[]) cached in 105ms, valid for 5min
 48:16 INFO [0;37mINFOm] main com.jcabi.dynamo.TableMocker: DynamoDB table 'stands' deletion requested
 48:16 INFO [0;37mINFOm] main com.jcabi.dynamo.TableMocker: DynamoDB table 'stands' deleted
 48:16 INFO [0;37mINFOm] main com.jcabi.dynamo.TableMocker: DynamoDB table 'stands' is ACTIVE
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStands: #create('test-stand'): in 229ms
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStands: #contains('test-stand'): true in 153ms
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStands: #contains('test-stand'): true cached in 154ms, valid for 5min
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStands: #contains('abc'): false in 51ms
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStands: #contains('abc'): false cached in 52ms, valid for 5min
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStands: #fetch(): 'AwsFrame(credentials=us-east-1/AAAAAAAAAAAAAAAAAA..288.. forward=true, attributes=[acl, widgets]))' cached in 1ms, valid for 5min
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStands: #iterator(): com.rultor.users.AwsStands$1@1069de79 in 3ms
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStand: #name(): 'test-stand' in 228µs
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStand: #name(): 'test-stand' cached in 6ms, valid for 5min
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStand: #owner(): urn:test:6 in 447µs
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStand: #owner(): urn:test:6 cached in 1ms, valid for 5min
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStands: #get('test-stand'): 'AwsStand(item=AwsItem(credentials=us-east-1/AAAAA..497..wner={S: urn:test:6,}, keys=owner, stand))' in 194ms
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStand: #owner(): urn:test:6 in 446µs
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.AwsStand: #owner(): urn:test:6 cached in 2ms, valid for 5min
 48:16 INFO [0;37mINFOm] main com.jcabi.dynamo.TableMocker: DynamoDB table 'stands' deletion requested
 48:16 INFO [0;37mINFOm] main com.jcabi.dynamo.TableMocker: DynamoDB table 'stands' deleted
 48:16 INFO Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.471 sec - in com.rultor.users.AwsStandsITCase
 48:16 INFO Running com.rultor.users.pgsql.PgSheetITCase
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #columns(): '[Column.Simple(name=id, grp=false, sum=false), Co..284...Simple(name=amount, grp=false, sum=true)]' in 52µs
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #columns(): '[Column.Simple(name=id, grp=false, sum=false), Co..284...Simple(name=amount, grp=false, sum=true)]' in 14µs
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #query(): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..217..1T18:41:08Z'\nGROUP BY dt\nLIMIT 50 OFFSET 0' in 3ms
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #groupBy('dt'): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..217..1T18:41:08Z'\nGROUP BY dt\nLIMIT 50 OFFSET 0' in 74ms
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #columns(): '[Column.Simple(name=id, grp=false, sum=false), Co..284...Simple(name=amount, grp=false, sum=true)]' in 13µs
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #query(): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..209..08Z'\nGROUP BY dt, dtrule\nLIMIT 50 OFFSET 0' in 2ms
 48:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #groupBy('dtrule'): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..209..08Z'\nGROUP BY dt, dtrule\nLIMIT 50 OFFSET 0' in 866µs
χemβly 'XPATH "/snapshot"; ADDIF "lines"; SET "6671";'
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #columns(): '[Column.Simple(name=id, grp=false, sum=false), Co..284...Simple(name=amount, grp=false, sum=true)]' in 10µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #query(): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..228..trule\nORDER BY _time ASC\nLIMIT 50 OFFSET 0' in 2ms
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #orderBy('time', true): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..228..trule\nORDER BY _time ASC\nLIMIT 50 OFFSET 0' in 838µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #columns(): '[Column.Simple(name=id, grp=false, sum=false), Co..284...Simple(name=amount, grp=false, sum=true)]' in 9µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #query(): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..238..R BY _id DESC, _time ASC\nLIMIT 50 OFFSET 0' in 2ms
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #orderBy('id', false): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..238..R BY _id DESC, _time ASC\nLIMIT 50 OFFSET 0' in 617µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #where(): com.rultor.users.pgsql.PgCondition@dd7a0dfa in 2ms
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgCondition: #equalTo('amount', '1'): com.rultor.users.pgsql.PgCondition@130b5ae0 in 134µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #columns(): '[Column.Simple(name=id, grp=false, sum=false), Co..284...Simple(name=amount, grp=false, sum=true)]' in 10µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #query(): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..278..R BY _id DESC, _time ASC\nLIMIT 50 OFFSET 0' in 2ms
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #with(' amount = $xLdkZxgJqu$1$xLdkZxgJqu$'): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..278..R BY _id DESC, _time ASC\nLIMIT 50 OFFSET 0' in 373µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #columns(): '[Column.Simple(name=id, grp=false, sum=false), Co..284...Simple(name=amount, grp=false, sum=true)]' in 9µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #query(): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..278..R BY _id DESC, _time ASC\nLIMIT 50 OFFSET 0' in 46ms
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgCondition: #sheet(): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..278..R BY _id DESC, _time ASC\nLIMIT 50 OFFSET 0' in 3ms
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #columns(): '[Column.Simple(name=id, grp=false, sum=false), Co..284...Simple(name=amount, grp=false, sum=true)]' in 11µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #query(): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..278..R BY _id DESC, _time ASC\nLIMIT 50 OFFSET 0' in 27ms
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #between(2013-10-29T18:41:08Z, 2013-10-31T18:41:08Z): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..278..R BY _id DESC, _time ASC\nLIMIT 50 OFFSET 0' in 417µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #columns(): '[Column.Simple(name=id, grp=false, sum=false), Co..284...Simple(name=amount, grp=false, sum=true)]' in 12µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #query(): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..278..R BY _id DESC, _time ASC\nLIMIT 50 OFFSET 2' in 2ms
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #tail(2): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..278..R BY _id DESC, _time ASC\nLIMIT 50 OFFSET 2' in 465µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #columns(): '[Column.Simple(name=id, grp=false, sum=false), Co..284...Simple(name=amount, grp=false, sum=true)]' in 10µs
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgSheet: #query(): 'SELECT MAX(id) AS _id, MAX(time) AS _time, MAX(ct..278..R BY _id DESC, _time ASC\nLIMIT 50 OFFSET 2' in 2ms
 56:16 INFO [2;37mDEBUGm] main com.rultor.users.pgsql.PgClient$Simple: #get(): 'JDBC URL = jdbc:postgresql://localhost:54956/test..109.. test period = 240 min, strategy = DEFAULT' from cache (hit #3, 17s old)
 56:16 INFO Thu Oct 31 18:41:18.745 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:1419 nreturned:0 reslen:20 1ms
 60:17 INFO [mongod output] Thu Oct 31 18:41:18.747 [DataFileSync] flushing mmaps took 57ms  for 4 files
 60:17 INFO [mongod output] Thu Oct 31 18:41:18.747 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:67 nreturned:0 reslen:20 0ms
 60:17 INFO [mongod output] Thu Oct 31 18:42:18.690 [DataFileSync] flushing mmaps took 0ms      for 4 files
 60:17 INFO [mongod output] Thu Oct 31 18:42:18.748 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:187 nreturned:0 reslen:20 0ms
 60:17 INFO [mongod output] Thu Oct 31 18:42:18.748 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:62 nreturned:0 reslen:20 0ms
 60:17 INFO [mongod output] [0;33mWARNm] jcabi-loggable com.jcabi.jdbc.JdbcSession: #select(com.rultor.users.pgsql.PgSheet$1@7a6eab98): takes more than 1min, 2min already, thread=main/TIMED_WAITING
 60:17 INFO Thu Oct 31 18:43:18.690 [DataFileSync] flushing mmaps took 0ms      for 4 files
 60:17 INFO [mongod output] Thu Oct 31 18:43:18.748 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:206 nreturned:0 reslen:20 0ms
 60:17 INFO [mongod output] Thu Oct 31 18:43:18.748 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:57 nreturned:0 reslen:20 0ms
 60:17 INFO [mongod output] [0;33mWARNm] jcabi-loggable com.jcabi.jdbc.JdbcSession: #select(com.rultor.users.pgsql.PgSheet$1@7a6eab98): takes more than 1min, 3min already, thread=main/TIMED_WAITING
 60:17 INFO Thu Oct 31 18:44:18.690 [DataFileSync] flushing mmaps took 0ms      for 4 files
 60:17 INFO [mongod output] Thu Oct 31 18:44:18.749 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:178 nreturned:0 reslen:20 0ms
 60:17 INFO [mongod output] Thu Oct 31 18:44:18.749 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:62 nreturned:0 reslen:20 0ms
 60:17 INFO [mongod output] [0;33mWARNm] jcabi-loggable com.jcabi.jdbc.JdbcSession: #select(com.rultor.users.pgsql.PgSheet$1@7a6eab98): takes more than 1min, 4min already, thread=main/TIMED_WAITING
 60:17 INFO Thu Oct 31 18:45:18.690 [DataFileSync] flushing mmaps took 0ms      for 4 files
 60:17 INFO [mongod output] Thu Oct 31 18:45:18.749 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:175 nreturned:0 reslen:20 0ms
 60:17 INFO [mongod output] Thu Oct 31 18:45:18.749 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:57 nreturned:0 reslen:20 0ms
 60:17 INFO [mongod output] [0;33mWARNm] jcabi-loggable com.jcabi.jdbc.JdbcSession: #select(com.rultor.users.pgsql.PgSheet$1@7a6eab98): takes more than 1min, 5min already, thread=main/TIMED_WAITING
 60:17 INFO Thu Oct 31 18:46:18.691 [DataFileSync] flushing mmaps took 0ms      for 4 files
 60:17 INFO [mongod output] Thu Oct 31 18:46:18.750 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:189 nreturned:0 reslen:20 0ms
 60:17 INFO [mongod output] Thu Oct 31 18:46:18.750 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:57 nreturned:0 reslen:20 0ms
 60:17 INFO [mongod output] [0;33mWARNm] jcabi-loggable com.jcabi.jdbc.JdbcSession: #select(com.rultor.users.pgsql.PgSheet$1@7a6eab98): takes more than 1min, 6min already, thread=main/TIMED_WAITING
 60:17 INFO Thu Oct 31 18:47:18.691 [DataFileSync] flushing mmaps took 0ms      for 4 files
 60:17 INFO [mongod output] Thu Oct 31 18:47:18.750 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:168 nreturned:0 reslen:20 0ms
χemβly 'XPATH "/snapshot"; ADDIF "lines"; SET "6718";'
 68:17 INFO [mongod output] Thu Oct 31 18:47:18.750 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:54 nreturned:0 reslen:20 0ms
 68:17 INFO [mongod output] [0;33mWARNm] jcabi-loggable com.jcabi.jdbc.JdbcSession: #select(com.rultor.users.pgsql.PgSheet$1@7a6eab98): takes more than 1min, 7min already, thread=main/TIMED_WAITING
 68:17 INFO Thu Oct 31 18:48:18.691 [DataFileSync] flushing mmaps took 0ms      for 4 files
 68:17 INFO [mongod output] Thu Oct 31 18:48:18.751 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:162 nreturned:0 reslen:20 0ms
 68:17 INFO [mongod output] Thu Oct 31 18:48:18.751 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:57 nreturned:0 reslen:20 0ms
 68:17 INFO [mongod output] [0;33mWARNm] jcabi-loggable com.jcabi.jdbc.JdbcSession: #select(com.rultor.users.pgsql.PgSheet$1@7a6eab98): takes more than 1min, 8min already, thread=main/TIMED_WAITING
 68:17 INFO Thu Oct 31 18:49:18.691 [DataFileSync] flushing mmaps took 0ms      for 4 files
 68:17 INFO [mongod output] Thu Oct 31 18:49:18.751 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:179 nreturned:0 reslen:20 0ms
 68:17 INFO [mongod output] Thu Oct 31 18:49:18.751 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:62 nreturned:0 reslen:20 0ms
 68:17 INFO [mongod output] [0;33mWARNm] jcabi-loggable com.jcabi.jdbc.JdbcSession: #select(com.rultor.users.pgsql.PgSheet$1@7a6eab98): takes more than 1min, 9min already, thread=main/TIMED_WAITING
 68:17 INFO Thu Oct 31 18:50:18.691 [DataFileSync] flushing mmaps took 0ms      for 4 files
 68:17 INFO [mongod output] Thu Oct 31 18:50:18.752 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:164 nreturned:0 reslen:20 0ms
 68:17 INFO [mongod output] Thu Oct 31 18:50:18.752 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:56 nreturned:0 reslen:20 0ms
 68:17 INFO [mongod output] [0;33mWARNm] jcabi-loggable com.jcabi.jdbc.JdbcSession: #select(com.rultor.users.pgsql.PgSheet$1@7a6eab98): takes more than 1min, 10min already, thread=main/TIMED_WAITING

... stays like this forever ...

@krzyk
Copy link

krzyk commented Nov 1, 2013

Created a bug jcabi/jcabi-jdbc#5
Version 0.10 always closed the connection, version 0.10.1 doesn't close connections at all, only opens new ones for each JdbcSession this leads to exhaustion of BoneCP connection pool.

@yegor256
Copy link
Owner Author

yegor256 commented Nov 2, 2013

@krzyk version 0.10.2 was released, please go on

krzyk pushed a commit to krzyk/rultor that referenced this issue Nov 3, 2013
yegor256#436 fixed by upgrading jcabi-jdbc
582a826
krzyk pushed a commit to krzyk/rultor that referenced this issue Nov 3, 2013
yegor256#436 fixed by upgading to jcabi-jdbc 0.10.2
e07c057
ghost pushed a commit that referenced this issue Nov 3, 2013
Merge pull request #438 from krzyk/436
67cbe1e 
#438: pull request #436 fixed by upgading to jcabi-jdbc 0.10.2
@yegor256
Copy link
Owner Author

yegor256 commented Dec 1, 2013

thanks!

@yegor256 yegor256 closed this as completed Dec 1, 2013
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@krzyk @yegor256