Slow dataloading with big datasets issue persists
{'login': 'hwijeen', 'id': 29157715, 'node_id': 'MDQ6VXNlcjI5MTU3NzE1', 'avatar_url': 'https://avatars.githubusercontent.com/u/29157715?v=4', 'gravatar_id': '', 'url': 'https://api.github.com/users/hwijeen', 'html_url': 'https://github.com/hwijeen', 'followers_url': 'https://api.github.com/users/hwijeen/followers', 'following_url': 'https://api.github.com/users/hwijeen/following{/other_user}', 'gists_url': 'https://api.github.com/users/hwijeen/gists{/gist_id}', 'starred_url': 'https://api.github.com/users/hwijeen/starred{/owner}{/repo}', 'subscriptions_url': 'https://api.github.com/users/hwijeen/subscriptions', 'organizations_url': 'https://api.github.com/users/hwijeen/orgs', 'repos_url': 'https://api.github.com/users/hwijeen/repos', 'events_url': 'https://api.github.com/users/hwijeen/events{/privacy}', 'received_events_url': 'https://api.github.com/users/hwijeen/received_events', 'type': 'User', 'site_admin': False}
[]
{'login': 'lhoestq', 'id': 42851186, 'node_id': 'MDQ6VXNlcjQyODUxMTg2', 'avatar_url': 'https://avatars.githubusercontent.com/u/42851186?v=4', 'gravatar_id': '', 'url': 'https://api.github.com/users/lhoestq', 'html_url': 'https://github.com/lhoestq', 'followers_url': 'https://api.github.com/users/lhoestq/followers', 'following_url': 'https://api.github.com/users/lhoestq/following{/other_user}', 'gists_url': 'https://api.github.com/users/lhoestq/gists{/gist_id}', 'starred_url': 'https://api.github.com/users/lhoestq/starred{/owner}{/repo}', 'subscriptions_url': 'https://api.github.com/users/lhoestq/subscriptions', 'organizations_url': 'https://api.github.com/users/lhoestq/orgs', 'repos_url': 'https://api.github.com/users/lhoestq/repos', 'events_url': 'https://api.github.com/users/lhoestq/events{/privacy}', 'received_events_url': 'https://api.github.com/users/lhoestq/received_events', 'type': 'User', 'site_admin': False}
[{'login': 'lhoestq', 'id': 42851186, 'node_id': 'MDQ6VXNlcjQyODUxMTg2', 'avatar_url': 'https://avatars.githubusercontent.com/u/42851186?v=4', 'gravatar_id': '', 'url': 'https://api.github.com/users/lhoestq', 'html_url': 'https://github.com/lhoestq', 'followers_url': 'https://api.github.com/users/lhoestq/followers', 'following_url': 'https://api.github.com/users/lhoestq/following{/other_user}', 'gists_url': 'https://api.github.com/users/lhoestq/gists{/gist_id}', 'starred_url': 'https://api.github.com/users/lhoestq/starred{/owner}{/repo}', 'subscriptions_url': 'https://api.github.com/users/lhoestq/subscriptions', 'organizations_url': 'https://api.github.com/users/lhoestq/orgs', 'repos_url': 'https://api.github.com/users/lhoestq/repos', 'events_url': 'https://api.github.com/users/lhoestq/events{/privacy}', 'received_events_url': 'https://api.github.com/users/lhoestq/received_events', 'type': 'User', 'site_admin': False}]
["Hi ! Sorry to hear that. This may come from another issue then.\r\n\r\nFirst can we check if this latency comes from the dataset itself ?\r\nYou can try to load your dataset and benchmark the speed of querying random examples inside it ?\r\n```python\r\nimport time\r\nimport numpy as np\r\n\r\nfrom datasets import load_from_disk\r\n\r\ndataset = load_from_disk(...) # or from load_dataset...\r\n\r\n_start = time.time()\r\nn = 100\r\nfor i in np.random.default_rng(42).integers(0, len(dataset), size=n):\r\n    _ = dataset[i]\r\nprint(time.time() - _start)\r\n```\r\n\r\nIf we see a significant speed difference between your two datasets then it would mean that there's an issue somewhere"
 "Hi @lhoestq, here is the result. I additionally measured time to `load_from_disk`:\r\n* 60GB\r\n```\r\nloading took:  22.618776321411133\r\nramdom indexing 100 times took: 0.10214924812316895\r\n```\r\n\r\n* 600GB\r\n```\r\nloading took:  1176.1764674186707\r\nramdom indexing 100 times took: 2.853600025177002\r\n```\r\n\r\nHmm.. I double checked that it's version 1.6.0. The difference seems quite big, could it be related to the running environment? \r\n"
 "I'm surprised by the speed change. Can you give more details about your dataset ?\r\nThe speed depends on the number of batches in the arrow tables and the distribution of the lengths of the batches.\r\nYou can access the batches by doing `dataset.data.to_batches()` (use only for debugging) (it doesn't bring data in memory).\r\n\r\nAlso can you explain what parameters you used if you used `map` calls ?\r\nAlso if you have some code that reproduces the issue I'd be happy to investigate it."
 "Also if you could give us more info about your env like your OS, version of pyarrow and if you're using an HDD or a SSD"
 'Here are some details of my 600GB dataset. This is a dataset AFTER the `map` function and once I load this dataset, I do not use `map` anymore in the training. Regarding the distribution of the lengths, it is almost uniform (90% is 512 tokens, and 10% is randomly shorter than that -- typical setting for language modeling).\r\n```\r\nlen(batches):\r\n492763\r\n\r\nbatches[0]: \r\npyarrow.RecordBatch\r\nattention_mask: list<item: uint8>\r\n  child 0, item: uint8\r\ninput_ids: list<item: int16>\r\n  child 0, item: int16\r\nspecial_tokens_mask: list<item: uint8>\r\n  child 0, item: uint8\r\ntoken_type_ids: list<item: uint8>\r\n  child 0, item: uint8\r\n```\r\n\r\nHere the some parameters to `map` function just in case it is relevant:\r\n```\r\nnum_proc=1    # as multi processing is slower in my case\r\nload_from_cache_file=False\r\n```\r\n'
 'Regarding the environment, I am running the code on a cloud server. Here are some info:\r\n```\r\nUbuntu 18.04.5 LTS   # cat /etc/issue\r\npyarrow                 3.0.0  # pip list | grep pyarrow\r\n```\r\nThe data is stored in SSD and it is mounted to the machine via Network File System.\r\n\r\nIf you could point me to some of the commands to check the details of the environment, I would be happy to provide relevant information @lhoestq !'
 'I am not sure how I could provide you with the reproducible code, since the problem only arises when the data is big. For the moment, I would share the part that I think is relevant. Feel free to ask me for more info.\r\n\r\n```python\r\nclass MyModel(pytorch_lightning.LightningModule)\r\n    def setup(self, stage):\r\n        self.dataset = datasets.load_from_disk(path)\r\n        self.dataset.set_format("torch")\r\n\r\n    def train_dataloader(self):\r\n        collate_fn = transformers.DataCollatorForLanguageModeling(\r\n                tokenizer=transformers.ElectraTokenizerFast.from_pretrained(tok_path)\r\n        )\r\n        dataloader = torch.utils.DataLoader(\r\n                self.dataset,\r\n                batch_size=32,\r\n                collate_fn=collate_fn,\r\n                num_workers=8,\r\n                pin_memory=True,\r\n       )\r\n```'
 "Hi ! Sorry for the delay I haven't had a chance to take a look at this yet. Are you still experiencing this issue ?\r\nI'm asking because the latest patch release 1.6.2 fixed a few memory issues that could have lead to slow downs"
 'Hi! I just ran the same code with different datasets (one is 60 GB and another 600 GB), and the latter runs much slower. ETA differs by 10x.'
 '@lhoestq and @hwijeen\r\n\r\nDespite upgrading to datasets 1.6.2, still experiencing extremely slow (2h00) loading for a 300Gb local dataset shard size 1.1Gb on local HDD (40Mb/s read speed). This corresponds almost exactly to total data divided by reading speed implying that it reads the entire dataset at each load.\r\n\r\nStack details:\r\n=========\r\n\r\n> GCC version: Could not collect\r\n> Clang version: Could not collect\r\n> CMake version: Could not collect\r\n> \r\n> Python version: 3.7 (64-bit runtime)\r\n> Is CUDA available: True\r\n> CUDA runtime version: 10.2.89\r\n> GPU models and configuration: GPU 0: GeForce GTX 1050\r\n> Nvidia driver version: 457.63\r\n> cuDNN version: C:\\Program Files\\NVIDIA GPU Computing Toolkit\\CUDA\\v10.2\\bin\\cudnn64_7.dll\r\n> HIP runtime version: N/A\r\n> MIOpen runtime version: N/A\r\n> \r\n> Versions of relevant libraries:\r\n> [pip3] datasets==1.6.2\r\n> [pip3] transformers==4.5.1\r\n> [pip3] numpy==1.19.1\r\n> [pip3] numpydoc==1.1.0\r\n> [pip3] pytorch-metric-learning==0.9.98\r\n> [pip3] torch==1.8.1\r\n> [pip3] torchaudio==0.8.1\r\n> [pip3] torchvision==0.2.2\r\n> [conda] blas                      2.16                        mkl    conda-forge\r\n> [conda] cudatoolkit               10.2.89              hb195166_8    conda-forge\r\n> [conda] libblas                   3.8.0                    16_mkl    conda-forge\r\n> [conda] libcblas                  3.8.0                    16_mkl    conda-forge\r\n> [conda] liblapack                 3.8.0                    16_mkl    conda-forge\r\n> [conda] liblapacke                3.8.0                    16_mkl    conda-forge\r\n> [conda] mkl                       2020.1                      216\r\n> [conda] numpy                     1.19.1           py37hae9e721_0    conda-forge\r\n> [conda] numpydoc                  1.1.0                      py_1    conda-forge\r\n> [conda] pytorch                   1.8.1           py3.7_cuda10.2_cudnn7_0    pytorch\r\n> [conda] pytorch-metric-learning   0.9.98             pyh39e3cac_0    metric-learning\r\n> [conda] torchaudio                0.8.1                      py37    pytorch\r\n> [conda] torchvision               0.2.2                      py_3    pytorch'
 'Hi @BenoitDalFerro how do your load your dataset ?'
 "Hi @lhoestq thanks for the quick turn-around, actually the plain vanilla way, without an particular knack or fashion, I tried to look into the documentation for some alternative but couldn't find any\r\n\r\n> dataset = load_from_disk(dataset_path=os.path.join(datasets_dir,dataset_dir))"
 'I’m facing the same issue when loading a 900GB dataset (stored via `save_to_disk`): `load_from_disk(path_to_dir)` takes 1.5 hours and htop consistently shows high IO rates > 120 M/s.'
 '@tsproisl same here, smells like ~~teen spirit~~ intended generator inadvertently ending up iterator\r\n\r\n@lhoestq perhaps solution to detect bug location in code is to track its signature via HD read usage monitoring, option is to add tracking decorator on top each function and sequentially close all hatches from top to bottom, suggest PySmart https://pypi.org/project/pySMART/ a Smartmontools implementation'
 'I wasn\'t able to reproduce this on a toy dataset of around 300GB:\r\n\r\n```python\r\nimport datasets as ds\r\n\r\ns = ds.load_dataset("squad", split="train")\r\ns4000 = ds.concatenate_datasets([s] * 4000)\r\nprint(ds.utils.size_str(s4000.data.nbytes))  # \'295.48 GiB\'\r\n\r\ns4000.save_to_disk("tmp/squad_4000")\r\n```\r\n\r\n```python\r\nimport psutil\r\nimport time\r\nfrom datasets import load_from_disk\r\n\r\ndisk = "disk0"  # You may have to change your disk here\r\niocnt1 = psutil.disk_io_counters(perdisk=True)[disk]\r\ntime1 = time.time()\r\n\r\ns4000_reloaded = load_from_disk("tmp/squad_4000")\r\n\r\ntime2 = time.time()\r\niocnt2 = psutil.disk_io_counters(perdisk=True)[disk]\r\n\r\nprint(f"Blocks read {iocnt2.read_count - iocnt1.read_count}")  # Blocks read 18\r\nprint(f"Elapsed time: {time2 - time1:.02f}s")  # Elapsed time: 14.60s\r\n```\r\n\r\nCould you run this on your side and tell me if how much time it takes ? Please run this when your machine is idle so that other processes don\'t interfere.\r\n\r\nI got these results on my macbook pro on datasets 1.6.2'
 '@lhoestq thanks, test running as we speak, bear with me'
 "Just tried on google colab and got ~1min for a 15GB dataset (only 200 times SQuAD), while it should be instantaneous. The time is spent reading the Apache Arrow table from the memory mapped file. This might come a virtual disk management issue. I'm trying to see if I can still speed it up on colab."
 "@lhoestq what is Google Colab's HD read speed, is it possible to introspect incl. make like SSD or HDD ?"
 "@lhoestq Thank you! The issue is getting more interesting. The second script is still running, but it's definitely taking much longer than 15 seconds."
 'Okay, here’s the ouput:\r\nBlocks read 158396\r\nElapsed time: 529.10s\r\n\r\nAlso using datasets 1.6.2. Do you have any ideas, how to pinpoint the problem?'
 '@lhoestq, @tsproisl mmmh still writing on my side about 1h to go, thinking on it are your large datasets all monoblock unsharded ? mine is 335 times 1.18Gb shards.'
 'The 529.10s was a bit too optimistic. I cancelled the reading process once before running it completely, therefore the harddrive cache probably did its work.\r\n\r\nHere are three consecutive runs\r\nFirst run (freshly written to disk):\r\nBlocks read 309702\r\nElapsed time: 1267.74s\r\nSecond run (immediately after):\r\nBlocks read 113944\r\nElapsed time: 417.55s\r\nThird run (immediately after):\r\nBlocks read 42518\r\nElapsed time: 199.19s\r\n'
 '@lhoestq \r\nFirst test\r\n> elapsed time: 11219.05s\r\n\r\nSecond test running bear with me, for Windows users slight trick to modify original "disk0" string:\r\n\r\nFirst find physical unit relevant key in dictionnary\r\n```\r\nimport psutil\r\npsutil.disk_io_counters(perdisk=True)\r\n```\r\n\r\n> {\'PhysicalDrive0\': sdiskio(read_count=18453286, write_count=4075333, read_bytes=479546467840, write_bytes=161590275072, read_time=20659, write_time=2464),\r\n>  \'PhysicalDrive1\': sdiskio(read_count=1495778, write_count=388781, read_bytes=548628622336, write_bytes=318234849280, read_time=426066, write_time=19085)}\r\n\r\nIn my case it\'s _PhysicalDrive1_\r\n\r\nThen insert relevant key\'s string as _disk_ variable\r\n\r\n```\r\npsutil.disk_io_counters()\r\ndisk = \'PhysicalDrive1\'  # You may have to change your disk here\r\niocnt1 = psutil.disk_io_counters(perdisk=True)[disk]\r\ntime1 = time.time()\r\ns4000_reloaded = load_from_disk("your path here")\r\ntime2 = time.time()\r\niocnt2 = psutil.disk_io_counters(perdisk=True)[disk]\r\nprint(f"Blocks read {iocnt2.read_count - iocnt1.read_count}")  # Blocks read 18\r\nprint(f"Elapsed time: {time2 - time1:.02f}s")  # Elapsed time: 14.60s\r\n```'
 '@lhoestq\r\nSecond test\r\n\r\n> Blocks read 1265609\r\n> Elapsed time: 11216.55s'
 '@lhoestq any luck ?'
 "Unfortunately no. Thanks for running the benchmark though, it shows that you machine does a lot of read operations. This is not expected: in other machines it does almost no read operations which enables a very fast loading.\r\n\r\nI did some tests on google colab and have the same issue. The first time the dataset arrow file is memory mapped takes always a lot of time (time seems linear with respect to the dataset size). Reloading the dataset is then instantaneous since the arrow file has already been memory mapped.\r\n\r\nI also tried using the Arrow IPC file format (see #1933) instead of the current streaming format that we use but it didn't help.\r\n\r\nMemory mapping is handled by the OS and depends on the disk you're using, so I'm not sure we can do much about it. I'll continue to investigate anyway, because I still don't know why in some cases it would go through the entire file (high `Blocks read ` as in your tests) and in other cases it would do almost no reading."
 "@lhoestq thanks for the effort, let's stay in touch"
 'Just want to say that I am seeing the same issue. Dataset size if 268GB and it takes **3 hours** to load `load_from_disk`, using dataset version `1.9.0`. Filesystem underneath is `Lustre` '
 'Hi @lhoestq, confirmed Windows issue, exact same code running on Linux OS total loading time about 3 minutes.'
 "Hmm that's different from what I got. I was on Ubuntu when reporting the initial issue."]
Hi,

I reported too slow data fetching when data is large(#2210) a couple of weeks ago, and @lhoestq referred me to the fix (#2122).
However, the problem seems to persist. Here is the profiled results:


1) Running with 60GB
```
Action                             	|  Mean duration (s)	|Num calls      	|  Total time (s) 	|  Percentage %   	|
------------------------------------------------------------------------------------------------------------------------------------
Total                              	|  -              	|_              	|  517.96         	|  100 %          	|
------------------------------------------------------------------------------------------------------------------------------------
model_backward                     	|  0.26144        	|100            	|  26.144         	|  5.0475         	|
model_forward                      	|  0.11123        	|100            	|  11.123         	|  2.1474         	|
get_train_batch                    	|  0.097121       	|100            	|  9.7121         	|  1.8751         	|
```


3) Running with 600GB, datasets==1.6.0
```
Action                             	|  Mean duration (s)	|Num calls      	|  Total time (s) 	|  Percentage %   	|
------------------------------------------------------------------------------------------------------------------------------------
Total                              	|  -              	|_              	|  4563.2         	|  100 %          	|
------------------------------------------------------------------------------------------------------------------------------------
get_train_batch                    	|  5.1279         	|100            	|  512.79         	|  11.237         	|
model_backward                     	|  4.8394         	|100            	|  483.94         	|  10.605         	|
model_forward                      	|  0.12162        	|100            	|  12.162         	|  0.26652        	|
```

I see that `get_train_batch` lags when data is large. Could this be related to different issues?
I would be happy to provide necessary information to investigate.
{'url': 'https://api.github.com/repos/huggingface/datasets/issues/2252/reactions', 'total_count': 1, '+1': 0, '-1': 0, 'laugh': 0, 'hooray': 0, 'confused': 0, 'heart': 0, 'rocket': 0, 'eyes': 1}