neo4j - Using relationship index on gremlin is relatively slow -

in neo4j, have relationship index 'index_e_assoc_smethdgexp' containing 180000 edges, attribute 'property'. want simple query lists 200 edges index, @ point regardless of property value (later query fetch same attribute values 200 first edge out vertices edge property <= 0.01), , fetch few attribute values out node:

time = system.currenttimemillis(); t = new table(); g.idx('index_e_assoc_smethdgexp')[[property: neo4jtokens.query_header + "*"]][0..200].outv().id.as('nodeid').back(1).alias.as("alias").back(1).chr.as('chr').table(t,["nodeid","alias","chr"]).iterate(); system.currenttimemillis() - time 

=713ms

getting 200 first edges index takes 262ms:

time = system.currenttimemillis(); g.idx('index_e_assoc_smethdgexp')[[property: neo4jtokens.query_header + "*"]][0..200]; system.currenttimemillis() - time 

why first query completed slowly? shouldn't take long 200 edges "predetermined list" , fetch few attribute values every output node. i'm complete newbie when comes cypher , gremlin, there faster way query, either in cypher or gremlin?

edit: ran query (1) 23 times:

==> 1124 ==> 983 ==> 951 ==> 864 ==> 1175 ==> 1189 ==> 889 ==> 917 ==> 822 ==> 872 ==> 795 ==> 736 ==> 840 ==> 1189 ==> 723 ==> 756 ==> 691 ==> 44609 ==> 644 ==> 640 ==> 1110 ==> 1007 ==> 819 

edit2: have since re-imported database following configuration:

dump_configuration=true cache_type=gcr neostore.nodestore.db.mapped_memory=100m neostore.relationshipstore.db.mapped_memory=4g neostore.propertystore.db.mapped_memory=200m neostore.propertystore.db.strings.mapped_memory=1g neostore.propertystore.db.arrays.mapped_memory=1g neostore.propertystore.db.index.keys.mapped_memory=1g neostore.propertystore.db.index.mapped_memory=1g relationship_cache_array_fraction=8 node_cache_array_fraction=8 node_cache_size=3g relationship_cache_size=6g 

now query(1) takes longer: 23849 ms. it's starting cache issue.

interesting snippets of db log:

2012-07-06 10:51:49,149 debug [neo4j.diagnostics]: system memory information: 2012-07-06 10:51:49,152 debug [neo4j.diagnostics]: total physical memory: 26,37 gb 2012-07-06 10:51:49,152 debug [neo4j.diagnostics]: free physical memory: 11,99 gb 2012-07-06 10:51:49,153 debug [neo4j.diagnostics]: committed virtual memory: 16,43 gb 2012-07-06 10:51:49,153 debug [neo4j.diagnostics]: total swap space: 27,00 gb 2012-07-06 10:51:49,153 debug [neo4j.diagnostics]: free swap space: 26,96 gb 2012-07-06 10:51:49,154 debug [neo4j.diagnostics]: jvm memory information: 2012-07-06 10:51:49,154 debug [neo4j.diagnostics]: free  memory: 1,84 gb 2012-07-06 10:51:49,154 debug [neo4j.diagnostics]: total memory: 1,87 gb 2012-07-06 10:51:49,154 debug [neo4j.diagnostics]: max   memory: 13,33 gb 2012-07-06 10:51:49,588 debug [neo4j.diagnostics]: storage files: 2012-07-06 10:51:49,589 debug [neo4j.diagnostics]: messages.log: 304,72 kb 2012-07-06 10:51:49,589 debug [neo4j.diagnostics]: neostore.propertystore.db.index: 1,02 kb 2012-07-06 10:51:49,589 debug [neo4j.diagnostics]: neostore.propertystore.db: 401,18 mb 2012-07-06 10:51:49,590 debug [neo4j.diagnostics]: neostore.relationshipstore.db.id: 9,00 b 2012-07-06 10:51:49,590 debug [neo4j.diagnostics]: index.db: 1,42 kb 2012-07-06 10:51:49,590 debug [neo4j.diagnostics]: tm_tx_log.1: 0,00 b 2012-07-06 10:51:49,590 debug [neo4j.diagnostics]: neostore.relationshiptypestore.db.names.id: 9,00 b 2012-07-06 10:51:49,591 debug [neo4j.diagnostics]: neostore.propertystore.db.id: 9,00 b 2012-07-06 10:51:49,591 debug [neo4j.diagnostics]: neostore.nodestore.db: 478,88 kb 2012-07-06 10:51:49,591 debug [neo4j.diagnostics]: nioneo_logical.log.active: 4,00 b 2012-07-06 10:51:49,591 debug [neo4j.diagnostics]: neostore.nodestore.db.id: 9,00 b 2012-07-06 10:51:49,591 debug [neo4j.diagnostics]: neostore.propertystore.db.strings.id: 9,00 b 2012-07-06 10:51:49,592 debug [neo4j.diagnostics]: neostore.id: 9,00 b 2012-07-06 10:51:49,592 debug [neo4j.diagnostics]: neostore.propertystore.db.strings: 34,15 mb 2012-07-06 10:51:49,592 debug [neo4j.diagnostics]: neostore.relationshiptypestore.db.id: 9,00 b 2012-07-06 10:53:01,486 info  [neo4j]: gc monitor: application threads blocked additional 14826ms [total block time: 14.826s] 2012-07-06 10:54:24,019 info  [neo4j]: gc monitor: application threads blocked additional 875ms [total block time: 15.701s] 2012-07-06 10:55:25,441 info  [neo4j]: gc monitor: application threads blocked additional 559ms [total block time: 16.26s] 2012-07-06 11:00:16,962 info  [neo4j]: gc monitor: application threads blocked additional 775ms [total block time: 17.035s] 

jvm parameters include

-xx:+disableexplicitgc -xms2000m, -xmx15360m 

it seems garbage collector interferes execution, why that? jvm params i'm telling server instance use max amount of ~15gb memory should plenty.

edit4: doing query(1) adds following log:

2012-07-06 11:40:31,973 info  [neo4j]: gc monitor: application threads blocked additional 23745ms [total block time: 23.745s] 2012-07-06 11:40:33,961 info  [neo4j]: relationshipcache array size: 17895751 purge count: 0 size is: 0b, 100.0% misses, nan% collisions (0). 2012-07-06 11:40:33,966 info  [neo4j]: nodecache array size: 17895751 purge count: 0 size is: 0b, 100.0% misses, nan% collisions (0). 

have tried running query multiple times, operating on warm graph , index?