Lots of individual SliceQuery results in .profile()

[joshluck]

Hello!

I'm running into some strange results when profiling my traversals; sometimes, when I introduce a .project(), .select(), .coalesce(), or .path() (which I've mostly avoided, as it's expensive per the docs), I generate a ton of individual optimizations + sliceQueries, with accordingly high durations for the group of queries (profile snippet below with a .coalesce() example).

Is this just to be expected with these steps/the JanusGraph implementation of TinkerPop? Ultimately, I want a grouped tuple of vertices w/ their properties (hence .project()/.select()), and I need to account for different vertex types (hence .coalesce()), so the traversal steps involved seem more-or-less necessary.

I wondered if this was related to #2185, but the slowness appears even without .profile(). I'm running JanusGraph v0.6.1 with query.batch=true, and I've tried toggling query.optimizer-backend-access without luck.

I appreciate any help you can give me! 🙂

Example (minimal) traversal:
g.V().has("id", "x").out("has_interface").both("link").dedup().coalesce(__.in("has_interface"), __.identity()).profile()

... profile of the first parts of the traversal, .out(), .both(), .dedup() all look fine/normal
{
  "dur": 725.881358,
  "counts": {
    "traverserCount": 581,
    "elementCount": 581
  },
  "name": "CoalesceStep([[JanusGraphMultiQueryStep, NoOpBarrierStep, JanusGraphVertexStep(IN,[has_interface],vertex)], [IdentityStep]])",
  "annotations": {
    "percentDur": 85.52726048251452
  },
  "id": "5.0.0()",
  "metrics": [
    {
      "dur": 3.708015,
      "counts": {
        "traverserCount": 581,
        "elementCount": 581
      },
      "name": "JanusGraphMultiQueryStep",
      "id": "0.1.0(5.0.0())"
    },
    {
      "dur": 1.485557,
      "counts": {
        "traverserCount": 581,
        "elementCount": 581
      },
      "name": "NoOpBarrierStep",
      "id": "2.1.0(5.0.0())"
    },
    {
      "dur": 715.441179,
      "counts": {
        "traverserCount": 581,
        "elementCount": 581
      },
      "name": "JanusGraphVertexStep(IN,[has_interface],vertex)",
      "annotations": {
        "condition": "type[has_interface]",
        "orders": "[]",
        "isFitted": "true",
        "isOrdered": "true",
        "query": "has_interface:SliceQuery[0x77A1,0x77A2)",
        "multi": "true",
        "vertices": 1
      },
      "id": "4.1.0(5.0.0())",
      "metrics": [
        {
          "dur": 0.037271,
          "counts": {},
          "name": "optimization",
          "id": "4.1.0(5.0.0()).optimization_0"
        },
        {
          "dur": 0.812777,
          "counts": {
            "elementCount": 1
          },
          "name": "backend-query",
          "annotations": {
            "query": "has_interface:SliceQuery[0x77A1,0x77A2)"
          },
          "id": "4.1.0(5.0.0()).backend-query_1"
        },
        ... more of the same
        {
          "dur": 0.012041,
          "counts": {},
          "name": "optimization",
          "id": "4.1.0(5.0.0()).optimization_1160"
        },
        {
          "dur": 0.942909,
          "counts": {
            "elementCount": 1
          },
          "name": "backend-query",
          "annotations": {
            "query": "has_interface:SliceQuery[0x77A1,0x77A2)"
          },
          "id": "4.1.0(5.0.0()).backend-query_1161"
        }
      ]
    },
    {
      "dur": 0,
      "counts": {},
      "name": "IdentityStep",
      "id": "0.1.1(5.0.0())"
    }
  ]
}

[li-boxuan]

Looks like your first part of the query,

g.V().has("id", "x").out("has_interface").both("link").dedup()

returns a lot of vertices. Then, for each vertex, JanusGraph fires a backend query to fetch

coalesce(__.in("has_interface"), __.identity())

So your profiler suggests that query.batch is not working for you. Looks like this is due to the coalesce step. This is a limitation of JanusGraph. It does not optimize every TinkerPop step.

What you could do is to split your query into two. In the first query, you run g.V().has("id", "x").out("has_interface").both("link").dedup() to fetch a list of vertices. Then, you use multi-threading to fire g.V(v).coalesce(__.in("has_interface"), __.identity()) queries concurrently. If you are using embedded JanusGraph (i.e. using JanusGraph as a java library), then there is no additional overhead. If you are using JanusGraph server, then unfortunately there is extra network overhead, but still, the performance should be better than your current state.

[joshluck]

Sorry for the delayed repsonse: thank you for the advice, we'll definitely try that out!

Whenever we run into these kind of profiling results (like with .valueMap() in #2444) , would you say it's a safe bet to try splitting the query and using client-side multithreading before continuing on? Also, would it be reasonable to create a similar issue to #2444 for .coalesce()?

[li-boxuan]

Good luck! And it is only my best guess that the slowness is due to coalesce step. If the query without coalesce (i.e. g.V().has("id", "x").out("has_interface").both("link").dedup().in("has_interface")) is also same slow (dedup might also be the curse here though I am not sure), please let me know ;)

would you say it's a safe bet to try splitting the query and using client-side multithreading before continuing on

Yes, I would say so. Actually, only the most common steps have native multi-threading support (e.g. values(), out(), in(), outE(), inE()).

would it be reasonable to create a similar issue to #2444 for .coalesce()

Yeah, that would make sense!

[joshluck]

Your best guess definitely makes sense to me; I remember from seeing similar results for .project() and .select(), I initially thought it was just a map step thing, but the .coalesce() was the smallest example I could put in a reasonable Q+A. I don't believe I saw the issue with just the .dedup(), like you mentioned.

Thanks again for your help! If only I were somewhat proficient in Java, I would've been happy to help hack on these -- maybe someday 😅