Reindex performance degrading logarithmically

[jsnod]

Hi! We're re-indexing a 7GB index, and noticed that performance starts out fast then logarithmically degrades over time:

We're using elasticsearch v1.7.3 and elasticsearch-py v1.9.0.

We're following all recommendations for increasing indexing performance, eg:

index.refresh_interval: -1
index.store.throttle.type: none
index.translog.flush_threshold_size: 1g
index.number_of_replicas: 0

Our cluster is at AWS and is comprised of the following:

• (5) m4.xlarge data nodes
• (3) m3.medium master nodes
• (1) m4.large client node

This cluster should be plenty beefy for indexing a paltry 7GB of data. The original indexing only took a couple of hours to complete, but this re-indexing has been going for nearly 24 hours and is only 70% done. And it only seems to be getting slower as time goes on. At this rate, the re-index will never finish.

We've tried various chunk sizes in the reindex() call, but it doesn't seem to affect performance so we're using the default of 500.

The python script is relatively chill, while ES is blasting away at the CPU:

Any ideas on what would cause this behavior? And how to get past it? I'm suspecting that there's an issue with scan/scroll. It's almost like the client needs to seek through all the previous chunks to get to the next chunk, so everything is getting slower the further it gets. But that's just a wild guess.

Fixing this is essential for completing our upgrade to ES 2.3, especially since we have indices that are 10x the size of this 7GB index that we will need to be reindexing as well. Thanks!

[honzakral]

Could you please share the exact code that you are using to do the reindex? Thanks!

[jsnod]

A minimal version of our code is below. I left out things like validating args, creating the targetIndex, writing the mappings, and modifying index settings (refresh_interval, etc...). The transform method just removes an unwanted field before passing along to bulk(). Note that we are seeing this behavior even when not passing in a transform argument. We're using the following optional args:

• args.eshost: 127.0.0.1
• args.clusterTimeout: 180
• args.chunksize: 500
• args.scroll: 5s

I'm fairly certain this is an issue with scroll/scan, as we're seeing the exact same issue as https://discuss.elastic.co/t/scrolling-performance/14560 . That thread doesn't describe the fix they used to solve this. I've put in some debug statements and have verified that scan is being properly set, which according to everything I read should be what avoids this issue. You can see that scan is being set as the search_type in the initial query:

{u'search_type': 'scan', u'fields': '_source,_parent,_routing,_timestamp', u'scroll': '5s'}

Code sample below:

from elasticsearch import Elasticsearch, exceptions
import threading
from time import sleep, time

def reIndex(args):
    def drawProgressBar(actual, expected, barLen=20):
        percent = 1 if expected == 0 else float(actual) / float(expected)
        progress = ""
        for i in range(barLen):
            if i < int(barLen * percent):
                progress += "="
            else:
                progress += " "
        fmt = "      Docs Indexed: %d / %d  [ %s ] %.2f%%    \r"
        sys.stdout.write(fmt % (actual, expected, progress, percent * 100))
        sys.stdout.flush()

    sourceCluster = Elasticsearch(
        hosts=args.eshost, 
        timeout=args.clusterTimeout, 
        max_retries=4, 
        retry_on_timeout=True)

    targetCluster = Elasticsearch(
        hosts=args.targetCluster, 
        timeout=args.clusterTimeout, 
        max_retries=4,
        retry_on_timeout=True)

    # if source and target cluster are the same, we don't need to specify the target
    # to the reindexer
    workerTargetClient = None if sourceCluster == targetCluster else targetCluster

    # count docs in source index so we can make sure we've copied them all
    sourceCount = sourceCluster.count(args.sourceIndex)['count']

    class ReIndexTransforms(object):
        @classmethod
        def transformES2(cls, action):
            docType = action['_type']
            docSource = action['_source']

            # remove erroneous 'oldField' field from some types
            if docType == 'account' or docType == 'user' and 'oldField' in docSource:
                docSource.pop('oldField', None)

            return cls.packageTransform(action, docSource)

        @classmethod
        def packageTransform(cls, action, source):
            actionLine = {
                'index': {
                    '_index': action['_index'],
                    '_type': action['_type'],
                    '_id': action['_id']
                }
            }

            # optional fields
            if '_parent' in action:
                actionLine['index']['_parent'] = action['_parent']
            if '_routing' in action:
                actionLine['index']['_routing'] = action['_routing']

            return (actionLine, source)

    ReIndexTransforms.LOOKUP = {
        'transformES2': {
            'doc': ReIndexTransforms.transformES2,
            'mappings': ReIndexTransforms.transformES2Mappings,
        },
    }

    def _doReindexWork():
        callback = ReIndexTransforms.LOOKUP.get(args.transform, {}).get('doc')
        bulkArgs = dict(expand_action_callback=callback) if callback else {}
        es_helpers.reindex(
            sourceCluster,
            args.sourceIndex,
            args.targetIndex,
            target_client=workerTargetClient,
            chunk_size=args.chunkSize,
            scroll=args.scroll,
            bulk_kwargs=bulkArgs)

    # start the hard work!
    worker = threading.Thread(target=_doReindexWork)
    worker.daemon = True  # so we can ctrl-c out if necessary
    worker.start()
    while worker.is_alive():
        drawProgressBar(targetCluster.count(args.targetIndex)['count'], sourceCount)
        sleep(1)

    # do an explicit refresh to make sure count api is accurate
    targetCluster.indices.refresh(args.targetIndex)

    # draw final progress bar to 100%
    drawProgressBar(targetCluster.count(args.targetIndex)['count'], sourceCount)

    print "\nReindexing complete!"

[honzakral]

The code looks good, could you try running just the scan to see how fast you can just go through the target index? If you could also try that with scroll size larger than 5s just to be sure.

Thanks

[jsnod]

Ok, I did just scan() on a ~2GB index and got some interesting results. You can see it starts out pretty quick then slowly degrades. Speeds up a bit at the end though, which is surprising. But based on what I've seen, if I did a larger index it would just keep getting worse.

A larger scroll size did not make much difference -- I saw very similar timings with larger scroll values.

Starting scan...
Scanned 100,000 docs (batch time: 0:00:08 / total time: 0:00:08 )
Scanned 200,000 docs (batch time: 0:00:14 / total time: 0:00:23 )
Scanned 300,000 docs (batch time: 0:00:16 / total time: 0:00:39 )
Scanned 400,000 docs (batch time: 0:00:18 / total time: 0:00:57 )
Scanned 500,000 docs (batch time: 0:00:22 / total time: 0:01:19 )
Scanned 600,000 docs (batch time: 0:00:25 / total time: 0:01:45 )
Scanned 700,000 docs (batch time: 0:00:29 / total time: 0:02:14 )
Scanned 800,000 docs (batch time: 0:00:33 / total time: 0:02:48 )
Scanned 900,000 docs (batch time: 0:00:38 / total time: 0:03:26 )
Scanned 1,000,000 docs (batch time: 0:00:41 / total time: 0:04:07 )
Scanned 1,100,000 docs (batch time: 0:00:45 / total time: 0:04:52 )
Scanned 1,200,000 docs (batch time: 0:00:50 / total time: 0:05:43 )
Scanned 1,300,000 docs (batch time: 0:00:53 / total time: 0:06:37 )
Scanned 1,400,000 docs (batch time: 0:00:58 / total time: 0:07:35 )
Scanned 1,500,000 docs (batch time: 0:01:02 / total time: 0:08:37 )
Scanned 1,600,000 docs (batch time: 0:01:06 / total time: 0:09:44 )
Scanned 1,700,000 docs (batch time: 0:01:05 / total time: 0:10:49 )
Scanned 1,800,000 docs (batch time: 0:01:01 / total time: 0:11:51 )
Scanned 1,900,000 docs (batch time: 0:00:55 / total time: 0:12:46 )
Scanned 2,000,000 docs (batch time: 0:00:54 / total time: 0:13:41 )
Scanned 2,100,000 docs (batch time: 0:01:00 / total time: 0:14:41 )
Scanned 2,200,000 docs (batch time: 0:01:02 / total time: 0:15:44 )
Scanned 2,300,000 docs (batch time: 0:01:07 / total time: 0:16:52 )
Scanned 2,400,000 docs (batch time: 0:00:51 / total time: 0:17:43 )
Scanned 2,500,000 docs (batch time: 0:00:44 / total time: 0:18:28 )
Scanned 2,600,000 docs (batch time: 0:00:32 / total time: 0:19:00 )
Scanned 2,700,000 docs (batch time: 0:00:34 / total time: 0:19:34 )
Scanned 2,800,000 docs (batch time: 0:00:35 / total time: 0:20:09 )
Scanned 2,900,000 docs (batch time: 0:00:41 / total time: 0:20:51 )
Scanned 3,000,000 docs (batch time: 0:00:40 / total time: 0:21:31 )
Scanned 3,100,000 docs (batch time: 0:00:35 / total time: 0:22:06 )
Scanned 3,200,000 docs (batch time: 0:00:37 / total time: 0:22:43 )
Scanned 3,300,000 docs (batch time: 0:00:46 / total time: 0:23:30 )
Scanned 3,400,000 docs (batch time: 0:00:34 / total time: 0:24:04 )
Scanned 3,440,029 docs in 0:24:17
DONE!

All I did was iterate over the scan results like so:

docs = es_helpers.scan(
    sourceCluster,
    index=args.sourceIndex,
    scroll=args.scroll,
    fields=('_source', '_parent', '_routing', '_timestamp')
)

totalCount = 0
batchCount = 0
batchSize = 100000
batchTime = time()

for d in docs:
    batchCount += 1
    totalCount += 1
    if batchCount == batchSize:
        print "Scanned", format(totalCount, ",d"), "docs (batch time:", _timeDiff(batchTime), \
            "/ total time:", _timeDiff(start), ")"
        batchCount = 0
        batchTime = time()

def _timeDiff(start):
    m, s = divmod(time() - start, 60)
    h, m = divmod(m, 60)
    return "%d:%02d:%02d" % (h, m, s)

[jsnod]

Just ran it on a much larger index (7GB) and it's much worse. It hasn't even gotten close to scanning all 27M docs in over 13 hours:

  Starting scan...
    Scanned 100,000 docs (batch time: 0:00:07 / total time: 0:00:07 )
    Scanned 200,000 docs (batch time: 0:00:11 / total time: 0:00:18 )
    Scanned 300,000 docs (batch time: 0:00:14 / total time: 0:00:33 )
    Scanned 400,000 docs (batch time: 0:00:18 / total time: 0:00:52 )
    Scanned 500,000 docs (batch time: 0:00:23 / total time: 0:01:15 )
    Scanned 600,000 docs (batch time: 0:00:26 / total time: 0:01:42 )
    Scanned 700,000 docs (batch time: 0:00:30 / total time: 0:02:13 )
    Scanned 800,000 docs (batch time: 0:00:34 / total time: 0:02:47 )
    Scanned 900,000 docs (batch time: 0:00:38 / total time: 0:03:25 )
    Scanned 1,000,000 docs (batch time: 0:00:41 / total time: 0:04:07 )
    Scanned 1,100,000 docs (batch time: 0:00:45 / total time: 0:04:53 )
    Scanned 1,200,000 docs (batch time: 0:00:49 / total time: 0:05:43 )
    Scanned 1,300,000 docs (batch time: 0:00:53 / total time: 0:06:36 )
    Scanned 1,400,000 docs (batch time: 0:00:58 / total time: 0:07:34 )
    Scanned 1,500,000 docs (batch time: 0:01:03 / total time: 0:08:37 )
    Scanned 1,600,000 docs (batch time: 0:01:06 / total time: 0:09:44 )
    Scanned 1,700,000 docs (batch time: 0:01:09 / total time: 0:10:54 )
    Scanned 1,800,000 docs (batch time: 0:01:13 / total time: 0:12:07 )
    Scanned 1,900,000 docs (batch time: 0:01:17 / total time: 0:13:24 )
    Scanned 2,000,000 docs (batch time: 0:01:20 / total time: 0:14:45 )
    Scanned 2,100,000 docs (batch time: 0:01:24 / total time: 0:16:10 )
    Scanned 2,200,000 docs (batch time: 0:01:34 / total time: 0:17:44 )
    Scanned 2,300,000 docs (batch time: 0:01:46 / total time: 0:19:30 )
    Scanned 2,400,000 docs (batch time: 0:01:37 / total time: 0:21:08 )
    Scanned 2,500,000 docs (batch time: 0:01:42 / total time: 0:22:50 )
    Scanned 2,600,000 docs (batch time: 0:01:50 / total time: 0:24:40 )
    Scanned 2,700,000 docs (batch time: 0:01:54 / total time: 0:26:34 )
    Scanned 2,800,000 docs (batch time: 0:01:54 / total time: 0:28:28 )
    Scanned 2,900,000 docs (batch time: 0:01:55 / total time: 0:30:23 )
    Scanned 3,000,000 docs (batch time: 0:02:05 / total time: 0:32:29 )
    Scanned 3,100,000 docs (batch time: 0:02:12 / total time: 0:34:42 )
    Scanned 3,200,000 docs (batch time: 0:02:13 / total time: 0:36:55 )
    Scanned 3,300,000 docs (batch time: 0:02:18 / total time: 0:39:14 )
    Scanned 3,400,000 docs (batch time: 0:02:14 / total time: 0:41:28 )
    Scanned 3,500,000 docs (batch time: 0:02:24 / total time: 0:43:53 )
    Scanned 3,600,000 docs (batch time: 0:02:40 / total time: 0:46:34 )
    Scanned 3,700,000 docs (batch time: 0:02:50 / total time: 0:49:25 )
    Scanned 3,800,000 docs (batch time: 0:02:37 / total time: 0:52:02 )
    Scanned 3,900,000 docs (batch time: 0:02:35 / total time: 0:54:38 )
    Scanned 4,000,000 docs (batch time: 0:02:37 / total time: 0:57:15 )
    Scanned 4,100,000 docs (batch time: 0:02:42 / total time: 0:59:58 )
    Scanned 4,200,000 docs (batch time: 0:02:45 / total time: 1:02:43 )
    Scanned 4,300,000 docs (batch time: 0:02:57 / total time: 1:05:40 )
    Scanned 4,400,000 docs (batch time: 0:03:02 / total time: 1:08:43 )
    Scanned 4,500,000 docs (batch time: 0:03:03 / total time: 1:11:46 )
    Scanned 4,600,000 docs (batch time: 0:03:12 / total time: 1:14:59 )
    Scanned 4,700,000 docs (batch time: 0:03:17 / total time: 1:18:16 )
    Scanned 4,800,000 docs (batch time: 0:03:15 / total time: 1:21:32 )
    Scanned 4,900,000 docs (batch time: 0:03:25 / total time: 1:24:57 )
    Scanned 5,000,000 docs (batch time: 0:03:23 / total time: 1:28:21 )
    Scanned 5,100,000 docs (batch time: 0:03:34 / total time: 1:31:55 )
    Scanned 5,200,000 docs (batch time: 0:03:37 / total time: 1:35:32 )
    Scanned 5,300,000 docs (batch time: 0:03:28 / total time: 1:39:01 )
    Scanned 5,400,000 docs (batch time: 0:03:37 / total time: 1:42:38 )
    Scanned 5,500,000 docs (batch time: 0:03:48 / total time: 1:46:27 )
    Scanned 5,600,000 docs (batch time: 0:03:54 / total time: 1:50:21 )
    Scanned 5,700,000 docs (batch time: 0:03:43 / total time: 1:54:04 )
    Scanned 5,800,000 docs (batch time: 0:03:46 / total time: 1:57:51 )
    Scanned 5,900,000 docs (batch time: 0:04:03 / total time: 2:01:55 )
    Scanned 6,000,000 docs (batch time: 0:04:09 / total time: 2:06:04 )
    Scanned 6,100,000 docs (batch time: 0:04:12 / total time: 2:10:17 )
    Scanned 6,200,000 docs (batch time: 0:04:07 / total time: 2:14:25 )
    Scanned 6,300,000 docs (batch time: 0:04:31 / total time: 2:18:56 )
    Scanned 6,400,000 docs (batch time: 0:04:20 / total time: 2:23:16 )
    Scanned 6,500,000 docs (batch time: 0:04:28 / total time: 2:27:45 )
    Scanned 6,600,000 docs (batch time: 0:04:22 / total time: 2:32:07 )
    Scanned 6,700,000 docs (batch time: 0:04:23 / total time: 2:36:31 )
    Scanned 6,800,000 docs (batch time: 0:04:38 / total time: 2:41:10 )
    Scanned 6,900,000 docs (batch time: 0:04:45 / total time: 2:45:56 )
    Scanned 7,000,000 docs (batch time: 0:04:56 / total time: 2:50:53 )
    Scanned 7,100,000 docs (batch time: 0:04:47 / total time: 2:55:40 )
    Scanned 7,200,000 docs (batch time: 0:04:56 / total time: 3:00:37 )
    Scanned 7,300,000 docs (batch time: 0:04:57 / total time: 3:05:34 )
    Scanned 7,400,000 docs (batch time: 0:05:04 / total time: 3:10:39 )
    Scanned 7,500,000 docs (batch time: 0:04:55 / total time: 3:15:34 )
    Scanned 7,600,000 docs (batch time: 0:05:14 / total time: 3:20:49 )
    Scanned 7,700,000 docs (batch time: 0:05:17 / total time: 3:26:06 )
    Scanned 7,800,000 docs (batch time: 0:05:12 / total time: 3:31:18 )
    Scanned 7,900,000 docs (batch time: 0:05:17 / total time: 3:36:36 )
    Scanned 8,000,000 docs (batch time: 0:05:32 / total time: 3:42:08 )
    Scanned 8,100,000 docs (batch time: 0:05:27 / total time: 3:47:36 )
    Scanned 8,200,000 docs (batch time: 0:05:44 / total time: 3:53:20 )
    Scanned 8,300,000 docs (batch time: 0:05:22 / total time: 3:58:43 )
    Scanned 8,400,000 docs (batch time: 0:05:32 / total time: 4:04:16 )
    Scanned 8,500,000 docs (batch time: 0:05:42 / total time: 4:09:59 )
    Scanned 8,600,000 docs (batch time: 0:05:48 / total time: 4:15:48 )
    Scanned 8,700,000 docs (batch time: 0:05:57 / total time: 4:21:45 )
    Scanned 8,800,000 docs (batch time: 0:06:00 / total time: 4:27:46 )
    Scanned 8,900,000 docs (batch time: 0:05:50 / total time: 4:33:37 )
    Scanned 9,000,000 docs (batch time: 0:06:00 / total time: 4:39:38 )
    Scanned 9,100,000 docs (batch time: 0:05:59 / total time: 4:45:38 )
    Scanned 9,200,000 docs (batch time: 0:06:16 / total time: 4:51:54 )
    Scanned 9,300,000 docs (batch time: 0:06:21 / total time: 4:58:15 )
    Scanned 9,400,000 docs (batch time: 0:06:22 / total time: 5:04:37 )
    Scanned 9,500,000 docs (batch time: 0:06:19 / total time: 5:10:57 )
    Scanned 9,600,000 docs (batch time: 0:06:11 / total time: 5:17:09 )
    Scanned 9,700,000 docs (batch time: 0:06:27 / total time: 5:23:36 )
    Scanned 9,800,000 docs (batch time: 0:06:19 / total time: 5:29:56 )
    Scanned 9,900,000 docs (batch time: 0:06:35 / total time: 5:36:32 )
    Scanned 10,000,000 docs (batch time: 0:06:42 / total time: 5:43:14 )
    Scanned 10,100,000 docs (batch time: 0:06:55 / total time: 5:50:10 )
    Scanned 10,200,000 docs (batch time: 0:06:48 / total time: 5:56:58 )
    Scanned 10,300,000 docs (batch time: 0:06:55 / total time: 6:03:54 )
    Scanned 10,400,000 docs (batch time: 0:06:45 / total time: 6:10:40 )
    Scanned 10,500,000 docs (batch time: 0:06:57 / total time: 6:17:37 )
    Scanned 10,600,000 docs (batch time: 0:07:04 / total time: 6:24:42 )
    Scanned 10,700,000 docs (batch time: 0:07:09 / total time: 6:31:52 )
    Scanned 10,800,000 docs (batch time: 0:07:11 / total time: 6:39:03 )
    Scanned 10,900,000 docs (batch time: 0:07:22 / total time: 6:46:25 )
    Scanned 11,000,000 docs (batch time: 0:07:38 / total time: 6:54:03 )
    Scanned 11,100,000 docs (batch time: 0:07:15 / total time: 7:01:19 )
    Scanned 11,200,000 docs (batch time: 0:07:27 / total time: 7:08:46 )
    Scanned 11,300,000 docs (batch time: 0:07:24 / total time: 7:16:11 )
    Scanned 11,400,000 docs (batch time: 0:07:32 / total time: 7:23:44 )
    Scanned 11,500,000 docs (batch time: 0:07:25 / total time: 7:31:09 )
    Scanned 11,600,000 docs (batch time: 0:07:31 / total time: 7:38:40 )
    Scanned 11,700,000 docs (batch time: 0:07:34 / total time: 7:46:15 )
    Scanned 11,800,000 docs (batch time: 0:07:48 / total time: 7:54:04 )
    Scanned 11,900,000 docs (batch time: 0:07:59 / total time: 8:02:04 )
    Scanned 12,000,000 docs (batch time: 0:07:44 / total time: 8:09:49 )
    Scanned 12,100,000 docs (batch time: 0:07:47 / total time: 8:17:36 )
    Scanned 12,200,000 docs (batch time: 0:08:05 / total time: 8:25:41 )
    Scanned 12,300,000 docs (batch time: 0:08:21 / total time: 8:34:02 )
    Scanned 12,400,000 docs (batch time: 0:08:06 / total time: 8:42:09 )
    Scanned 12,500,000 docs (batch time: 0:08:30 / total time: 8:50:39 )
    Scanned 12,600,000 docs (batch time: 0:08:07 / total time: 8:58:46 )
    Scanned 12,700,000 docs (batch time: 0:08:40 / total time: 9:07:26 )
    Scanned 12,800,000 docs (batch time: 0:09:11 / total time: 9:16:38 )
    Scanned 12,900,000 docs (batch time: 0:08:31 / total time: 9:25:09 )
    Scanned 13,000,000 docs (batch time: 0:08:28 / total time: 9:33:38 )
    Scanned 13,100,000 docs (batch time: 0:08:48 / total time: 9:42:26 )
    Scanned 13,200,000 docs (batch time: 0:09:04 / total time: 9:51:30 )
    Scanned 13,300,000 docs (batch time: 0:08:34 / total time: 10:00:05 )
    Scanned 13,400,000 docs (batch time: 0:09:04 / total time: 10:09:09 )
    Scanned 13,500,000 docs (batch time: 0:08:47 / total time: 10:17:57 )
    Scanned 13,600,000 docs (batch time: 0:08:51 / total time: 10:26:48 )
    Scanned 13,700,000 docs (batch time: 0:08:48 / total time: 10:35:37 )
    Scanned 13,800,000 docs (batch time: 0:09:02 / total time: 10:44:39 )
    Scanned 13,900,000 docs (batch time: 0:09:23 / total time: 10:54:03 )
    Scanned 14,000,000 docs (batch time: 0:09:22 / total time: 11:03:26 )
    Scanned 14,100,000 docs (batch time: 0:09:22 / total time: 11:12:49 )
    Scanned 14,200,000 docs (batch time: 0:09:31 / total time: 11:22:20 )
    Scanned 14,300,000 docs (batch time: 0:09:14 / total time: 11:31:35 )
    Scanned 14,400,000 docs (batch time: 0:09:33 / total time: 11:41:08 )
    Scanned 14,500,000 docs (batch time: 0:09:45 / total time: 11:50:54 )
    Scanned 14,600,000 docs (batch time: 0:09:46 / total time: 12:00:40 )
    Scanned 14,700,000 docs (batch time: 0:09:29 / total time: 12:10:10 )
    Scanned 14,800,000 docs (batch time: 0:09:43 / total time: 12:19:54 )
    Scanned 14,900,000 docs (batch time: 0:09:43 / total time: 12:29:37 )
    Scanned 15,000,000 docs (batch time: 0:09:40 / total time: 12:39:17 )
    Scanned 15,100,000 docs (batch time: 0:10:09 / total time: 12:49:27 )
    Scanned 15,200,000 docs (batch time: 0:10:10 / total time: 12:59:37 )
    Scanned 15,300,000 docs (batch time: 0:10:06 / total time: 13:09:44 )

[corey-hammerton]

You might also want to check your ES logs and node performance statistics to make sure there isn't anything funky going on elsewhere.

[jsnod]

One interesting thing I've found is that ES appears to be returning the same _scroll_id on subsequent scroll requests. But the ES docs clearly specify:

The initial search request and each subsequent scroll request returns a new _scroll_id — only the most recent _scroll_id should be used.

The scan() helper is definitely using the most recent _scroll_id, but should I expect to see a different _scroll_id on subsequent requests?

Also, I turned on slow logging during the scan:

sourceCluster.indices.put_settings({
    "index": {
        "search": {
            "slowlog": {
                "threshold": {
                    "query": {
                        "warn": "10s",
                        "info": "5s",
                        "debug": "2s",
                        "trace": "500ms",
                    },
                    "fetch": {
                        "warn": "1s",
                        "info": "800ms",
                        "debug": "500ms",
                        "trace": "200ms",
                    }
                }
            }
        }
    }
}, args.sourceIndex)

But nothing is showing in the slow logs.

Here is my hot_threads output in case this sheds any light:

::: [estest][PiocenKcQCuuF-82oB7EZw][estest.domain.com][inet[/172.31.9.171:9300]]{master=true}
   Hot threads at 2016-05-02T20:23:39.940Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

   31.4% (156.9ms out of 500ms) cpu usage by thread 'elasticsearch[estest][search][T#3]'
     2/10 snapshots sharing following 15 elements
       org.apache.lucene.search.Weight$DefaultBulkScorer.scoreAll(Weight.java:193)
       org.apache.lucene.search.Weight$DefaultBulkScorer.score(Weight.java:163)
       org.apache.lucene.search.BulkScorer.score(BulkScorer.java:35)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621)
       org.elasticsearch.search.internal.ContextIndexSearcher.search(ContextIndexSearcher.java:191)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:309)
       org.elasticsearch.search.scan.ScanContext.execute(ScanContext.java:52)
       org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:120)
       org.elasticsearch.search.SearchService.executeScan(SearchService.java:274)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:520)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:517)
       org.elasticsearch.search.action.SearchServiceTransportAction$23.run(SearchServiceTransportAction.java:559)
       java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
       java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
       java.lang.Thread.run(Thread.java:745)
     4/10 snapshots sharing following 19 elements
       org.apache.lucene.search.BitsFilteredDocIdSet.match(BitsFilteredDocIdSet.java:60)
       org.apache.lucene.search.FilteredDocIdSet$2.match(FilteredDocIdSet.java:103)
       org.apache.lucene.search.FilteredDocIdSetIterator.nextDoc(FilteredDocIdSetIterator.java:60)
       org.apache.lucene.search.ConstantScoreQuery$ConstantScorer.nextDoc(ConstantScoreQuery.java:257)
       org.apache.lucene.search.Weight$DefaultBulkScorer.scoreAll(Weight.java:192)
       org.apache.lucene.search.Weight$DefaultBulkScorer.score(Weight.java:163)
       org.apache.lucene.search.BulkScorer.score(BulkScorer.java:35)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621)
       org.elasticsearch.search.internal.ContextIndexSearcher.search(ContextIndexSearcher.java:191)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:309)
       org.elasticsearch.search.scan.ScanContext.execute(ScanContext.java:52)
       org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:120)
       org.elasticsearch.search.SearchService.executeScan(SearchService.java:274)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:520)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:517)
       org.elasticsearch.search.action.SearchServiceTransportAction$23.run(SearchServiceTransportAction.java:559)
       java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
       java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
       java.lang.Thread.run(Thread.java:745)
     2/10 snapshots sharing following 10 elements
       sun.misc.Unsafe.park(Native Method)
       java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
       java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:735)
       java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:644)
       java.util.concurrent.LinkedTransferQueue.take(LinkedTransferQueue.java:1137)
       org.elasticsearch.common.util.concurrent.SizeBlockingQueue.take(SizeBlockingQueue.java:162)
       java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
       java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
       java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
       java.lang.Thread.run(Thread.java:745)
     2/10 snapshots sharing following 17 elements
       org.apache.lucene.search.FilteredDocIdSetIterator.nextDoc(FilteredDocIdSetIterator.java:59)
       org.apache.lucene.search.ConstantScoreQuery$ConstantScorer.nextDoc(ConstantScoreQuery.java:257)
       org.apache.lucene.search.Weight$DefaultBulkScorer.scoreAll(Weight.java:192)
       org.apache.lucene.search.Weight$DefaultBulkScorer.score(Weight.java:163)
       org.apache.lucene.search.BulkScorer.score(BulkScorer.java:35)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621)
       org.elasticsearch.search.internal.ContextIndexSearcher.search(ContextIndexSearcher.java:191)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:309)
       org.elasticsearch.search.scan.ScanContext.execute(ScanContext.java:52)
       org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:120)
       org.elasticsearch.search.SearchService.executeScan(SearchService.java:274)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:520)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:517)
       org.elasticsearch.search.action.SearchServiceTransportAction$23.run(SearchServiceTransportAction.java:559)
       java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
       java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
       java.lang.Thread.run(Thread.java:745)

   27.8% (139ms out of 500ms) cpu usage by thread 'elasticsearch[estest][search][T#4]'
     6/10 snapshots sharing following 19 elements
       org.apache.lucene.search.BitsFilteredDocIdSet.match(BitsFilteredDocIdSet.java:60)
       org.apache.lucene.search.FilteredDocIdSet$2.match(FilteredDocIdSet.java:103)
       org.apache.lucene.search.FilteredDocIdSetIterator.nextDoc(FilteredDocIdSetIterator.java:60)
       org.apache.lucene.search.ConstantScoreQuery$ConstantScorer.nextDoc(ConstantScoreQuery.java:257)
       org.apache.lucene.search.Weight$DefaultBulkScorer.scoreAll(Weight.java:192)
       org.apache.lucene.search.Weight$DefaultBulkScorer.score(Weight.java:163)
       org.apache.lucene.search.BulkScorer.score(BulkScorer.java:35)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621)
       org.elasticsearch.search.internal.ContextIndexSearcher.search(ContextIndexSearcher.java:191)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:309)
       org.elasticsearch.search.scan.ScanContext.execute(ScanContext.java:52)
       org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:120)
       org.elasticsearch.search.SearchService.executeScan(SearchService.java:274)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:520)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:517)
       org.elasticsearch.search.action.SearchServiceTransportAction$23.run(SearchServiceTransportAction.java:559)
       java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
       java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
       java.lang.Thread.run(Thread.java:745)
     4/10 snapshots sharing following 2 elements
       java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
       java.lang.Thread.run(Thread.java:745)

   27.7% (138.2ms out of 500ms) cpu usage by thread 'elasticsearch[estest][search][T#1]'
     3/10 snapshots sharing following 19 elements
       org.apache.lucene.search.BitsFilteredDocIdSet.match(BitsFilteredDocIdSet.java:60)
       org.apache.lucene.search.FilteredDocIdSet$2.match(FilteredDocIdSet.java:103)
       org.apache.lucene.search.FilteredDocIdSetIterator.nextDoc(FilteredDocIdSetIterator.java:60)
       org.apache.lucene.search.ConstantScoreQuery$ConstantScorer.nextDoc(ConstantScoreQuery.java:257)
       org.apache.lucene.search.Weight$DefaultBulkScorer.scoreAll(Weight.java:192)
       org.apache.lucene.search.Weight$DefaultBulkScorer.score(Weight.java:163)
       org.apache.lucene.search.BulkScorer.score(BulkScorer.java:35)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621)
       org.elasticsearch.search.internal.ContextIndexSearcher.search(ContextIndexSearcher.java:191)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:309)
       org.elasticsearch.search.scan.ScanContext.execute(ScanContext.java:52)
       org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:120)
       org.elasticsearch.search.SearchService.executeScan(SearchService.java:274)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:520)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:517)
       org.elasticsearch.search.action.SearchServiceTransportAction$23.run(SearchServiceTransportAction.java:559)
       java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
       java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
       java.lang.Thread.run(Thread.java:745)
     2/10 snapshots sharing following 16 elements
       org.apache.lucene.search.ConstantScoreQuery$ConstantScorer.nextDoc(ConstantScoreQuery.java:257)
       org.apache.lucene.search.Weight$DefaultBulkScorer.scoreAll(Weight.java:192)
       org.apache.lucene.search.Weight$DefaultBulkScorer.score(Weight.java:163)
       org.apache.lucene.search.BulkScorer.score(BulkScorer.java:35)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621)
       org.elasticsearch.search.internal.ContextIndexSearcher.search(ContextIndexSearcher.java:191)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:309)
       org.elasticsearch.search.scan.ScanContext.execute(ScanContext.java:52)
       org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:120)
       org.elasticsearch.search.SearchService.executeScan(SearchService.java:274)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:520)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:517)
       org.elasticsearch.search.action.SearchServiceTransportAction$23.run(SearchServiceTransportAction.java:559)
       java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
       java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
       java.lang.Thread.run(Thread.java:745)
     2/10 snapshots sharing following 15 elements
       org.apache.lucene.search.Weight$DefaultBulkScorer.scoreAll(Weight.java:193)
       org.apache.lucene.search.Weight$DefaultBulkScorer.score(Weight.java:163)
       org.apache.lucene.search.BulkScorer.score(BulkScorer.java:35)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621)
       org.elasticsearch.search.internal.ContextIndexSearcher.search(ContextIndexSearcher.java:191)
       org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:309)
       org.elasticsearch.search.scan.ScanContext.execute(ScanContext.java:52)
       org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:120)
       org.elasticsearch.search.SearchService.executeScan(SearchService.java:274)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:520)
       org.elasticsearch.search.action.SearchServiceTransportAction$21.call(SearchServiceTransportAction.java:517)
       org.elasticsearch.search.action.SearchServiceTransportAction$23.run(SearchServiceTransportAction.java:559)
       java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
       java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
       java.lang.Thread.run(Thread.java:745)
     3/10 snapshots sharing following 10 elements
       sun.misc.Unsafe.park(Native Method)
       java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
       java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:735)
       java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:644)
       java.util.concurrent.LinkedTransferQueue.take(LinkedTransferQueue.java:1137)
       org.elasticsearch.common.util.concurrent.SizeBlockingQueue.take(SizeBlockingQueue.java:162)
       java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
       java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
       java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
       java.lang.Thread.run(Thread.java:745)

[jsnod]

This is looking to me more like a core Elasticsearch issue with scan/scroll rather than something in the Python client library. Is this the expected behavior of scan/scroll? If not, what's the protocol for getting feedback from the ES core team?

[ddorian]

Hmm, this maybe is a problem with your shitty ec2 hardware. I do plenty of times scans of ~11M documents spread over 20-shards that complete very fast (like ~40K/second). Though I'm on es 2.2/2.3 and have more memory than data.

To get feedback from the es team you can go to:::

1. irc (where they can say to add an issue)
2. forums
3. issues on github
   Are the old version still maintained or just for security fixes ?

[jsnod]

@ddorian Isn't the whole point of scan/scroll being able to page deep into a result set without having to load the whole thing into memory? I was under the impression that scan/scroll was one of the ways to not need to have "non-shitty ec2 hardware." I mean, we're only talking a 7GB index here, it's not like it's a giant index. I would certainly hope that ES can handle a 7GB index using (5) m4.xlarge data nodes. That's 20 CPUs and 80GB RAM.

I've submitted to all of the above (IRC, forums, Github issues) and haven't gotten any response other than in this thread.

Unfortunately we are unable to move to 2.2/2.3 until we get past this roadblock. The whole point of this reindex is to update our mappings for 2.2/2.3!

[ddorian]

Yeah you're right, it's a small index.

Try bumping the forum + issue (that's what i've done before).

So you can't even just scroll (without reindexing)?

[jsnod]

@ddorian The benchmarks I posted above were just from iterating over scan() results. No indexing. My code is posted above as well.

[ddorian]

Have you tried with searching, and getting only _ids, with a size of , say, 10K, and giving bigger offsets ? (and then doing multi-gets, or even try also with getting _source)
I know this is less efficient, but maybe the scanning code is broken, and your index fits in ram, and this should work better than your current scan.

[karmi]

Hi @jsnod, the best way to contact the Elasticsearch core team with a technical issue like this one (a reproducible problem) is to open an issue at the Github repository: https://github.com/elastic/elasticsearch