Profile() seems inconsisten with System.currentTimeMillis


HadoopMarc <bi...@...>
 


Hi,

Can anyone explain why the total duration displayed by the profile() step is more than twice as large as the time difference clocked with System.currentTimeMillis?
see below, For those who wonder, the query without profile() also takes about 300 msec.

Thanks,      Marc

gremlin> start = System.currentTimeMillis()
==>1607676127027
gremlin> g.V().has('serial', within('1654145144','1648418968','1652445288','1654952168','1653379120', '1654325440','1653383216','1658298568','1649680536','1649819672','1654964456','1649729552', '1656103144','1655460032','1656111336','1654669360')).inE('assembled').outV().profile()
==>Traversal Metrics
Step                                                               Count  Traversers       Time (ms)    % Dur
=============================================================================================================
JanusGraphStep([],[serial.within([1654145144, 1...                    16          16           0,486    59,26
    \_condition=((serial = 1654145144 OR serial = 1648418968 OR serial = 1652445288 OR serial = 1654952168 OR
               serial = 1653379120 OR serial = 1654325440 OR serial = 1653383216 OR serial = 1658298568 OR se
               rial = 1649680536 OR serial = 1649819672 OR serial = 1654964456 OR serial = 1649729552 OR seri
               al = 1656103144 OR serial = 1655460032 OR serial = 1656111336 OR serial = 1654669360))
    \_orders=[]
    \_isFitted=true
    \_isOrdered=true
    \_query=multiKSQ[16]@2000
    \_index=bySerial
  optimization                                                                                 0,009
  optimization                                                                                 0,267
JanusGraphVertexStep(IN,[assembled],vertex)                           73          73           0,334    40,74
    \_condition=type[assembled]
    \_orders=[]
    \_isFitted=true
    \_isOrdered=true
    \_query=org.janusgraph.diskstorage.keycolumnvalue.SliceQuery@812bd43d
    \_vertices=1
  optimization                                                                                 0,037
  optimization                                                                                 0,008
  optimization                                                                                 0,005
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,017
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
                                            >TOTAL                     -           -           0,820        -
gremlin> System.currentTimeMillis() - start
==>322



HadoopMarc <bi...@...>
 

In the mean time I found that the difference between profile() and currentTimeMillis can be much larger. Apparently, the profile() step takes into account that for real queries, vertices are not present in the database cache and assumes some time duration to retrieve a vertex or properties from the backend. Is there any documentation on these assumptions?

Best wishes,    Marc

Op vrijdag 11 december 2020 om 09:58:21 UTC+1 schreef HadoopMarc:


Hi,

Can anyone explain why the total duration displayed by the profile() step is more than twice as large as the time difference clocked with System.currentTimeMillis?
see below, For those who wonder, the query without profile() also takes about 300 msec.

Thanks,      Marc

gremlin> start = System.currentTimeMillis()
==>1607676127027
gremlin> g.V().has('serial', within('1654145144','1648418968','1652445288','1654952168','1653379120', '1654325440','1653383216','1658298568','1649680536','1649819672','1654964456','1649729552', '1656103144','1655460032','1656111336','1654669360')).inE('assembled').outV().profile()
==>Traversal Metrics
Step                                                               Count  Traversers       Time (ms)    % Dur
=============================================================================================================
JanusGraphStep([],[serial.within([1654145144, 1...                    16          16           0,486    59,26
    \_condition=((serial = 1654145144 OR serial = 1648418968 OR serial = 1652445288 OR serial = 1654952168 OR
               serial = 1653379120 OR serial = 1654325440 OR serial = 1653383216 OR serial = 1658298568 OR se
               rial = 1649680536 OR serial = 1649819672 OR serial = 1654964456 OR serial = 1649729552 OR seri
               al = 1656103144 OR serial = 1655460032 OR serial = 1656111336 OR serial = 1654669360))
    \_orders=[]
    \_isFitted=true
    \_isOrdered=true
    \_query=multiKSQ[16]@2000
    \_index=bySerial
  optimization                                                                                 0,009
  optimization                                                                                 0,267
JanusGraphVertexStep(IN,[assembled],vertex)                           73          73           0,334    40,74
    \_condition=type[assembled]
    \_orders=[]
    \_isFitted=true
    \_isOrdered=true
    \_query=org.janusgraph.diskstorage.keycolumnvalue.SliceQuery@812bd43d
    \_vertices=1
  optimization                                                                                 0,037
  optimization                                                                                 0,008
  optimization                                                                                 0,005
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,017
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
  optimization                                                                                 0,004
                                            >TOTAL                     -           -           0,820        -
gremlin> System.currentTimeMillis() - start
==>322