CSG: Changing user password incredibly slow

[hermitdemschoenenleb]

I’m running CSG 3.0.9 and Couchbase Server 7.1.1. Lately, a strange problem started to appear: changing CSG user passwords for existing users via POST to the _user REST api is incredibly slow (sometimes > 1 minute). However, setting a password for new users is fast (< 1s).

I tried to debug the problem:

• When changing password of an existing users, sg_info.log contains entries like 2025-07-01T17:42:16.792+02:00 [INF] Query: N1QL Query("sessions") took 1m1.327559001s
• in the “slowest completed queries” section of couchbase server interface I see plans like these:
  
  

→ if I interpret it correctly, this means that:

• the syncDocs index emits nearly 100k keys (I just checked: 100k is also the total number of _sync:session:% docs in my DB)
• these 100k keys are fetched ← this seems to be the slow step
• after they were fetched, only a single document is emitted

Strangely, my cluster has been working flawlessly for ages. This slowness only appeared after I upgraded my servers recently and increased indexer RAM – but I don’t see how this could be connected.

Do you have any idea what’s going on / how to fix the problem? Thanks a lot!

[bbrks]

We have some upcoming improvements to have more targeted indexes for users and roles, which will avoid unrelated _sync documents (like session docs).

In the meantime, I would probably check that the session documents you’re seeing have a TTL set. By default Sync Gateway is going to be creating these session documents with an expiry of only 24 hours, so seeing 100k is somewhat surprising.

I’m not sure what the reason for the sudden behavioral change would be after server-side upgrades.

[torcolvin]

I encourage thinking about this as an indexing problem rather than a Sync Gateway problem. The query for user docs will be dwarfed by the query when doing a replication, presuming there are more actual documents than user documents.

My guess would be that upgrading the Server nodes causes some of this index to drop out of memory and fall back to quite slow disks.

This index only contains the keys of documents and 98k keys should be on a the small megabytes level of data and quick to query.

[hermitdemschoenenleb]

thank you so much for your quick replies!

In the meantime, I would probably check that the session documents you’re seeing have a TTL set

they all do have a value for expiration. We currently have ~ 30k daily active users, so while 100k is still too much for some reason, it is at least on the same order of magnitude.

My guess would be that upgrading the Server nodes causes some of this index to drop out of memory and fall back to quite slow disks.

the sg_syncDocs_x1 index has a data size of ~ 400 MB which should be easy to keep in memory (max indexer memory is 25 GB, other indexes on this node are rather small with a total of << 25GB)

Also, what I find strange are the timings in this slow query plan:

If I understand it correctly, the index scan takes only 94ms, but what makes the query slow is actually the Fetch process which takes 1 minute (or am I mistaken here?). But I can’t see why the Fetch process became so slow (everything else on our system behaves normally). Do you have any idea what could cause this?

[vsr1]

Will u able to post text based plan (or query that run and index definition).
Filter Input is 100K and output is 1. May be index is not right one

[hermitdemschoenenleb]

Sure! Index definition is

CREATE INDEX `sg_syncDocs_x1` ON `data`((meta().`id`)) WHERE ((meta().`id`) like "\\_sync:%") WITH {  "defer_build":true }

Plan text is

{
  "#operator": "Authorize",
  "#stats": {
    "#phaseSwitches": 4,
    "execTime": "1.312µs",
    "servTime": "21.471µs"
  },
  "privileges": {
    "List": [
      {
        "Target": "default:data",
        "Priv": 7,
        "Props": 0
      }
    ]
  },
  "~child": {
    "#operator": "Sequence",
    "#stats": {
      "#phaseSwitches": 2,
      "execTime": "1.123µs"
    },
    "~children": [
      {
        "#operator": "IndexScan3",
        "#stats": {
          "#heartbeatYields": 1,
          "#itemsOut": 98612,
          "#phaseSwitches": 394451,
          "execTime": "67.883489ms",
          "kernTime": "31.444514503s",
          "servTime": "195.272787ms"
        },
        "index": "sg_syncDocs_x1",
        "index_id": "b769618f79b35a8",
        "index_projection": {
          "primary_key": true
        },
        "keyspace": "data",
        "namespace": "default",
        "spans": [
          {
            "exact": true,
            "range": [
              {
                "high": "\"_sync:session;\"",
                "inclusion": 1,
                "index_key": "(meta().`id`)",
                "low": "\"_sync:session:\""
              }
            ]
          }
        ],
        "using": "gsi"
      },
      {
        "#operator": "Fetch",
        "#stats": {
          "#heartbeatYields": 647,
          "#itemsIn": 98612,
          "#itemsOut": 98574,
          "#phaseSwitches": 394916,
          "execTime": "203.963309ms",
          "kernTime": "264.188039ms",
          "servTime": "31.253204066s"
        },
        "keyspace": "data",
        "namespace": "default"
      },
      {
        "#operator": "Sequence",
        "#stats": {
          "#phaseSwitches": 2,
          "execTime": "221.362µs",
          "kernTime": "300ns",
          "state": "running"
        },
        "~children": [
          {
            "#operator": "Filter",
            "#stats": {
              "#itemsIn": 98574,
              "#phaseSwitches": 197152,
              "execTime": "577.530756ms",
              "kernTime": "31.144537623s"
            },
            "condition": "((((meta(`data`).`id`) like \"\\\\_sync:%\") and ((meta(`data`).`id`) like \"\\\\_sync:session:%\")) and ((`data`.`username`) = $userName))"
          },
          {
            "#operator": "InitialProject",
            "#stats": {
              "#phaseSwitches": 6,
              "execTime": "13.086µs",
              "kernTime": "31.722092133s"
            },
            "result_terms": [
              {
                "expr": "(meta(`data`).`id`)"
              }
            ]
          }
        ]
      },
      {
        "#operator": "Stream",
        "#stats": {
          "#phaseSwitches": 2,
          "execTime": "681ns"
        }
      }
    ]
  },
  "~versions": [
    "7.1.1-N1QL",
    "7.1.1-3175-community"
  ]
}

[vsr1]

@hermitdemschoenenleb

{
        "#operator": "Fetch",
        "#stats": {
          "#heartbeatYields": 647,
          "#itemsIn": 98612,
          "#itemsOut": 98574,
          "#phaseSwitches": 394916,
          "execTime": "203.963309ms",
          "kernTime": "264.188039ms",
          "servTime": "31.253204066s"
        },

Fetch doing 98K documents and took 31.253204066s
As this CE query service uses only 4 cores. Also depends on what queries running at that time.

{
            "#operator": "Filter",
            "#stats": {
              "#itemsIn": 98574,
              "#phaseSwitches": 197152,
              "execTime": "577.530756ms",
              "kernTime": "31.144537623s"
            },

If look at filter 98K input, 0 output all work is discarded.
Best way push the filter to indexer.
With out impacting any thing best way achieve this add username to index

DROP INDEX sg_syncDocs_x1 ON data;
CREATE INDEX `sg_syncDocs_x1` ON `data`((meta().`id`), username) WHERE ((meta().`id`) like "\\_sync:%") WITH {  "defer_build":true };
BUILD INDEX ON data(sg_syncDocs_x1);

As this sync gateway hope this okay. cc @torcolvin

[hermitdemschoenenleb]

I created a new index that also includes username field, now everything’s fast again! Thanks a lot everybody for this great support!