Slow data processing within Flask-Pymongo

Working with Data Python Frameworks
,
1

Hello, I’m kind of a novice with MongoDB. I started using 2 years ago and now I’m having some problems with it.

State of Art
I’m using Flask and Flask-Pymongo to connect to my database which runs on a different machine and the connection between the 2 works thanks to a VPN tunnel.

The problem
Queries by themselves work fine, they usually take a bunch of milliseconds (got this result through some logging) but when I start iterating over the cursor given back from the find( ) method I start noticing a serious slowdown. I iterate over the cursor using a simple for loop but the time to start with the first iteration is endless, it takes from 20-25 seconds up while for the successive iterations it works normally.

Some testing

  • I have already tried converting the cursor retrieved into an array but this operation becomes the one that takes ages
  • I built another Flask server on the machine on which runs MongoDB to convert the cursor into an array and then passing it to the first server in order to check if the delay was due to the connection

System Infos

Server with Flask and Flask-Pymongo (hosted through DigitalOcean):

  • 8 vCPUs
  • 16GB RAM
  • 160GB of storage (SSD)
  • Ubuntu 20.04.1 LTS
  • Flask version: 1.0.2
  • Flask-Pymongo version: 2.2.0

Server with MongoDB (local machine):

  • Intel Xeon E5-2650
  • 64GB RAM
  • 16TB of storage (HDD)
  • Ubuntu 20.04.3 LTS
  • MongoDB version: 3.6.8
2

Edit
A further inspection of the MongoDB log following a certain query affected by the aforementioned problem pointed this out:

2022-07-31T18:47:53.970+0200 I NETWORK  [conn10699] received client metadata from x.x.x.x:yyyyy conn10699: { driver: { name: "PyMongo", version: "3.11.0" }, os: { type: "Linux", name: "Linux", architecture: "x86_64", version: "5.4.0-99-generic" }, platform: "CPython 3.8.12.final.0" }
2022-08-03T18:03:40.995+0200 D COMMAND  [conn10699] run command myDB.$cmd { find: "myColl", filter: { ... }, lsid: { id: UUID("043da910-3a33-49a3-a749-5ba84a20cf53") }, $db: "myDB", $readPreference: { mode: "primaryPreferred" } }
2022-08-03T18:03:40.996+0200 D STORAGE  [conn10699] NamespaceUUIDCache: registered namespace myDB.myColl with UUID 4b4e693d-e72b-4dab-a4de-0ca15618a93c
2022-08-03T18:03:40.996+0200 D QUERY    [conn10699] Tagging the match expression according to cache data: 
2022-08-03T18:03:40.996+0200 D QUERY    [conn10699] Index 0: _id_
2022-08-03T18:03:40.996+0200 D QUERY    [conn10699] Index 1: timestamp_1
2022-08-03T18:03:40.996+0200 D QUERY    [conn10699] Index 2: index2_1
2022-08-03T18:03:40.996+0200 D QUERY    [conn10699] Tagged tree:
2022-08-03T18:03:40.996+0200 D QUERY    [conn10699] Planner: solution constructed from the cache:
2022-08-03T18:03:40.996+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184330476
2022-08-03T18:03:41.041+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184330476
2022-08-03T18:03:41.042+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184331391
2022-08-03T18:03:41.044+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184331391
2022-08-03T18:03:41.044+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184331423
2022-08-03T18:03:41.079+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184331423
2022-08-03T18:03:41.080+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184332035
2022-08-03T18:03:41.125+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184332035
2022-08-03T18:03:41.125+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184332608
2022-08-03T18:03:41.157+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184332608
2022-08-03T18:03:41.157+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184333162
2022-08-03T18:03:41.231+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184333162
2022-08-03T18:03:41.231+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184334386
2022-08-03T18:03:41.399+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184334386 was 168ms
2022-08-03T18:03:41.399+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184334386
2022-08-03T18:03:41.399+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184337302
2022-08-03T18:03:41.429+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184337302
2022-08-03T18:03:41.429+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184337920
2022-08-03T18:03:41.561+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184337920 was 131ms
2022-08-03T18:03:41.561+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184337920
2022-08-03T18:03:41.561+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184339906
2022-08-03T18:03:41.696+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184339906 was 134ms
2022-08-03T18:03:41.696+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184339906
2022-08-03T18:03:41.696+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184342481
2022-08-03T18:03:41.914+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184342481 was 218ms
2022-08-03T18:03:41.914+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184342481
2022-08-03T18:03:41.915+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184345334
2022-08-03T18:03:42.110+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184345334 was 195ms
2022-08-03T18:03:42.110+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184345334
2022-08-03T18:03:42.110+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184348869
2022-08-03T18:03:42.216+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184348869 was 105ms
2022-08-03T18:03:42.216+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184348869
2022-08-03T18:03:42.217+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184350693
2022-08-03T18:03:42.283+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184350693
2022-08-03T18:03:42.284+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184351440
2022-08-03T18:03:42.504+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184351440 was 219ms
2022-08-03T18:03:42.504+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184351440
2022-08-03T18:03:42.505+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184354257
2022-08-03T18:03:42.559+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184354257
2022-08-03T18:03:42.560+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184355080
2022-08-03T18:03:42.575+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184355080
2022-08-03T18:03:42.575+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184355269
2022-08-03T18:03:42.608+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184355269
2022-08-03T18:03:42.609+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184355652
2022-08-03T18:03:42.623+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184355652
2022-08-03T18:03:42.623+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184355819
2022-08-03T18:03:42.730+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184355819 was 106ms
2022-08-03T18:03:42.730+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184355819
2022-08-03T18:03:42.731+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184357261
2022-08-03T18:03:42.870+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184357261 was 139ms
2022-08-03T18:03:42.870+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184357261
2022-08-03T18:03:42.870+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184359828
2022-08-03T18:03:42.909+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184359828
2022-08-03T18:03:42.909+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184360596
2022-08-03T18:03:42.982+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184360596
2022-08-03T18:03:42.983+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184361835
2022-08-03T18:03:43.080+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184361835
2022-08-03T18:03:43.080+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184362969
2022-08-03T18:03:43.204+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184362969 was 123ms
2022-08-03T18:03:43.204+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184362969
2022-08-03T18:03:43.204+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184364388
2022-08-03T18:03:43.284+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184364388
2022-08-03T18:03:43.284+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184365614
2022-08-03T18:03:43.446+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184365614 was 161ms
2022-08-03T18:03:43.446+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184365614
2022-08-03T18:03:43.446+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184367034
2022-08-03T18:03:43.626+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184367034 was 180ms
2022-08-03T18:03:43.627+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184367034
2022-08-03T18:03:43.628+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184369200

...

2022-08-03T18:03:50.668+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184453150
2022-08-03T18:03:50.668+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184453699
2022-08-03T18:03:50.685+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184453699
2022-08-03T18:03:50.685+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184453896
2022-08-03T18:03:50.727+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184453896
2022-08-03T18:03:50.727+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184454569
2022-08-03T18:03:50.849+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184454569 was 121ms
2022-08-03T18:03:50.849+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184454569
2022-08-03T18:03:50.849+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184455869
2022-08-03T18:03:50.955+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184455869 was 106ms
2022-08-03T18:03:50.955+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184455869
2022-08-03T18:03:50.956+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184456419
2022-08-03T18:03:51.254+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184456419 was 297ms
2022-08-03T18:03:51.254+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184456419
2022-08-03T18:03:51.254+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184458830
2022-08-03T18:03:51.301+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184458830
2022-08-03T18:03:51.301+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184459071
2022-08-03T18:03:51.535+0200 D STORAGE  [conn10699] Slow WT transaction. Lifetime of SnapshotId 31184459071 was 233ms
2022-08-03T18:03:51.535+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184459071
2022-08-03T18:03:51.535+0200 D STORAGE  [conn10699] WT begin_transaction for snapshot id 31184461290
2022-08-03T18:03:51.545+0200 D QUERY    [conn10699] score(1.01162) = baseScore(1) + productivity((44 advanced)/(3814 works) = 0.0115364) + tieBreakers(2.62192e-05 noFetchBonus + 2.62192e-05 noSortBonus + 2.62192e-05 noIxisectBonus = 7.86576e-05)
2022-08-03T18:03:51.547+0200 D STORAGE  [conn10699] WT rollback_transaction for snapshot id 31184461290
2022-08-03T18:03:51.548+0200 I COMMAND  [conn10699] command myDB.myColl command: find { find: "myColl", filter: { ... }, lsid: { id: UUID("043da910-3a33-49a3-a749-5ba84a20cf53") }, $db: "myDB", $readPreference: { mode: "primaryPreferred" } } planSummary: IXSCAN { index2: 1 } keysExamined:3813 docsExamined:3813 cursorExhausted:1 numYields:115 nreturned:44 reslen:18967 locks:{ Global: { acquireCount: { r: 232 } }, Database: { acquireCount: { r: 116 } }, Collection: { acquireCount: { r: 116 } } } protocol:op_msg 10552ms

P.S. I removed some lines of the log but the ones i removed contain the same stuff again and again