Skip to content
This repository has been archived by the owner on Feb 12, 2024. It is now read-only.

Lag on catReadableStream (possibly other stream methods as well) #1706

Closed
lifeBCE opened this issue Nov 10, 2018 · 9 comments · Fixed by libp2p/js-libp2p-bootstrap#86
Closed

Lag on catReadableStream (possibly other stream methods as well) #1706

lifeBCE opened this issue Nov 10, 2018 · 9 comments · Fixed by libp2p/js-libp2p-bootstrap#86
Labels
exp/expert Having worked on the specific codebase is important kind/bug A bug in existing code (including security flaws) P2 Medium: Good to have, but can wait until someone steps up

Comments

@lifeBCE
Copy link

lifeBCE commented Nov 10, 2018

  • Version:
    0.33.1

  • Platform:
    Mac OS X 10.12.6
    Chrome: Version 70.0.3538.77 (Official Build) (64-bit)
    FireFox: 63.0.1 (64-bit)

  • Subsystem:
    ?

Type:

Bug (maybe Enhancement?)

Severity:

High

Description:

When using js-ipfs as a client in a browser, executing node.files.catReadableStream starts the blocks streaming into the websocket connections immediately but it takes sometimes over 10 seconds before the stream triggers the first data event.

Basically, more than 10 seconds of lag between these two lines:

    this.stream = this.state.node.files.catReadableStream(hash)
    this.stream.on('data', (block) => {});

But as soon as the first line is executed, I see blocks coming across the websocket instantly. Is this by design or is there a problem here?

Steps to reproduce the error:

  1. Load up js-ipfs package in browser session.
  2. Start a browser node
  3. Once peers are connected, call catReadableStream on any hash (larger files work better as the process is really over before you know what happened on smaller files)
@lifeBCE lifeBCE mentioned this issue Nov 13, 2018
Closed
@alanshaw alanshaw added the status/duplicate This issue or pull request already exists label Nov 14, 2018
@alanshaw
Copy link
Member

alanshaw commented Nov 14, 2018 •
edited
Loading

Closing this as a duplicate of #1709 - let me know if that doesn't sound right @lifeBCE

@lifeBCE
Copy link
Author

lifeBCE commented Nov 14, 2018 •
edited
Loading

@alanshaw I don't think these are the same but could be the same cause? #1709 sounds like it is taking 8 seconds to transfer a local file from one local peer to another and does not seem to have anything to do with the websocket functionality.

My issue is that the embedded browser node from js-ipfs is pulling the blocks from the bootstrap node over the websocket connection but the data event is not fired on the stream for like 10+ seconds while the blocks are coming through the stream instantly.

I was thinking at first that it could be blocks that are out of order coming in first and the lag is due to waiting for the initial blocks to construct the beginning of the stream but then remembered reading something in the white paper for IPFS that said that beginning blocks are sent first to avoid such an issue?

@alanshaw
Copy link
Member

alanshaw commented Nov 19, 2018 •
edited
Loading

@lifeBCE is the first data event being triggered after the full response is received?

@lifeBCE
Copy link
Author

lifeBCE commented Nov 19, 2018

@alanshaw It does eventually get triggered but it doesn't seem to be after the full download completes. It seems to be about the same 8-10 seconds regardless of the size of the file. I have tested this against small 30 second video clips as well as an over 2 hour video and the lag time is the same for both and any length in between.

I have added some additional logic to my service to pre-load the first 5 MB of the next video in order to combat this lag a bit and that does seem to help. Pre-loaded videos show about only a 2 second lag before the data event is fired.

@alanshaw alanshaw added kind/bug A bug in existing code (including security flaws) exp/expert Having worked on the specific codebase is important status/ready Ready to be worked P2 Medium: Good to have, but can wait until someone steps up and removed status/duplicate This issue or pull request already exists labels Dec 4, 2018
@alanshaw alanshaw reopened this Dec 4, 2018
@lifeBCE
Copy link
Author

lifeBCE commented Dec 4, 2018 •
edited
Loading

Did some initial digging.

According to pull-defer docs (https://github.com/pull-stream/pull-defer) when using a deferred source stream, the stream is started when resolve is called as it is here.

js-ipfs/src/core/components/files-regular.js

Line 249 in ac5fa8e

d.resolve(content) 

//nothing will happen until deferred.resolve(stream) is called.
deferred.resolve(input)

The logic above is called from the public function definition here:

js-ipfs/src/core/components/files-regular.js

Line 382 in ac5fa8e

catReadableStream: (ipfsPath, options) => toStream.source(_catPullStream(ipfsPath, options)),

I started honing in on toStream as a potential culprit and this is where my investigation has stopped. The docs on pull-stream-to-stream are a bit vague to say the least. https://github.com/pull-stream/pull-stream-to-stream

Doing some A/B testing (maybe benchmarking) between catPullStream and catReadableStream may give some insight as both call the internal _catPullStream function but only catReadableStream calls toStream.

    catReadableStream: (ipfsPath, options) => toStream.source(_catPullStream(ipfsPath, options)),

    catPullStream: (ipfsPath, options) => _catPullStream(ipfsPath, options),

This is where the data event is emitted (in the pull-stream-to-stream logic). This is the trigger for the stream that lags for me in my code.
https://github.com/pull-stream/pull-stream-to-stream/blob/master/index.js#L101

Looks like something is lagging when calling the drain function.

@alanshaw
Copy link
Member

alanshaw commented Dec 7, 2018

@lifeBCE a few things I think you can check/do:

  1. can you confirm that this behaviour does not happen when you use catPullStream?
  2. if you pipe the stream to a writable does it still take 10s for the frist write?
  3. a runnable example of this problem would help considerably...

@lifeBCE
Copy link
Author

lifeBCE commented Dec 10, 2018 •
edited by alanshaw
Loading

@alanshaw

  1. I have confirmed that it happens on both pull and readable streams.
  2. I believe so but am not too familiar with this process so check my results.
  3. See below.
const IPFS = require('ipfs');
const pull = require('pull-stream')
const type = process.argv[2];

console.log('Instantiating IPFS node');
const node = new IPFS();
const hash = 'QmRm5YAWoudjGj926YKc2PuBFX7vTp2YzqbWFdmqyqWRQS';
const streamFunc = type === 'readable' ? node.files.catReadableStream : node.files.catPullStream;
let dataEvent = false;

node.on('ready', () => {
  console.log('IPFS node is ready');
  const readyTime = Math.floor(Date.now() / 1000);
  const stream = streamFunc(hash, { offset: 0,  length: 5000000 });
  console.log('Stream has been created, waiting for data....');

  const pullable = () => {
    pull(
      stream,
      pull.concat((err, data) => {
        if (!dataEvent) {
          dataEvent = true;
          const dataTime = Math.floor(Date.now() / 1000);
          console.log('Stream is receiving data: ' + Math.floor(dataTime - readyTime) + ' seconds');
        }
      })
    )
  }

  const readable = () => {
    stream.on('data', (block) => {
      if (!dataEvent) {
        dataEvent = true;
        const dataTime = Math.floor(Date.now() / 1000);
        console.log('Stream is receiving data: ' + Math.floor(dataTime - readyTime) + ' seconds');
      }
    })

    stream.on('end', () => node.stop());
  }

  type === 'readable' ? readable() : pullable();
})

node.on('error', error => {
  console.error(error.message);
})

Execute like:

$ node streamable.js readable
$ node streamable.js pullable

Don't forget to blow away your local cache after each run or the next run will be invalid (0 seconds).

Example Output:

Instantiating IPFS node
Swarm listening on /ip4/127.0.0.1/tcp/4003/ws/ipfs/QmUW6c2LNcZwmVPCppAvBDCNTGFKSNW7y68hKWjhFnjaj7
Swarm listening on /ip4/127.0.0.1/tcp/4002/ipfs/QmUW6c2LNcZwmVPCppAvBDCNTGFKSNW7y68hKWjhFnjaj7
Swarm listening on /ip4/192.168.2.4/tcp/4002/ipfs/QmUW6c2LNcZwmVPCppAvBDCNTGFKSNW7y68hKWjhFnjaj7
IPFS node is ready
Stream has been created, waiting for data....
Stream is receiving data: 13 seconds

The hash is a large video file of some IPFS demo from a couple years ago that has been formatted as DASH. The contents of the file is not super important, just needed a larger file to ensure that it wasn't lagging waiting until the complete file downloaded.

This example logic here generates a 12-13 second lag repeatedly for me when using either stream.

@alanshaw
Copy link
Member

alanshaw commented Jan 2, 2019 •
edited
Loading

Looking into this I've opened a PR ipfs-inactive/js-ipfs-unixfs-exporter#13 which shaves a number of seconds off the time to first byte, but the significant delay of around 10s remains.

It's worth noting that your node needs to receive some blocks before it can start emitting data, as has to do a depth first traversal before it gets to the node with the first byte of data.

UPDATE: if I add a 15s timeout after the node is ready and then start the cat stream then the time to first byte is 4s, with ipfs-inactive/js-ipfs-unixfs-exporter#13 it is reduced to 2s. This hints that the problem is not actually with fetching data from other nodes but potentially an issue with bootstrapping, and initiating connections to other nodes:

(there's some extra logging in here that I've added)

Before:

$ rm -rf ~/.jsipfs && node slow-cat2.js
Instantiating IPFS node
ipld got block QmZTR5bcpQD7cFgTorqxZDYaew1Wqgfbd2ud9QqGPAkK2V
ipld got block QmYCvbfNbCwFR45HiNP45rwJgvatpiW38D961L5qAhUM5Y
ipld got block QmQN88TEidd3RY2u3dpib49fERTDfKtDpvxnvczATNsfKT
ipld got block QmPZ9gcCEpqKTo6aq61g2nXGUhM4iCL3ewB6LDXZCtioEB
ipld got block QmY5heUM5qgRubMDD1og9fhCPA6QdkMp3QCwd4s7gJsyE7
ipld got block QmdncfsVm2h5Kqq9hPmU7oAVX2zTSVP3L869tgTbPYnsha
ipld got block QmYE7xo6NxbHEVEHej1yzxijYaNY51BaeKxjXxn6Ssa6Bs
ipld got block QmQ5vhrL7uv6tuoN9KeVBwd4PwfQkXdVVmDLUZuTNxqgvm
ipld got block QmegvLXxpVKiZ4b57Xs1syfBVRd8CbucVHAp7KpLQdGieC
ipld got block QmciSU8hfpAXKjvK5YLUSwApomGSWN5gFbP4EpDAEzu2Te
ipld got block QmfGBRT6BbWJd7yUc2uYdaUZJBbnEFvTqehPFoSMQ6wgdr
ipld got block QmfGBRT6BbWJd7yUc2uYdaUZJBbnEFvTqehPFoSMQ6wgdr
ipld got block QmZTR5bcpQD7cFgTorqxZDYaew1Wqgfbd2ud9QqGPAkK2V
ipld got block QmYCvbfNbCwFR45HiNP45rwJgvatpiW38D961L5qAhUM5Y
ipld got block QmdncfsVm2h5Kqq9hPmU7oAVX2zTSVP3L869tgTbPYnsha
ipld got block QmegvLXxpVKiZ4b57Xs1syfBVRd8CbucVHAp7KpLQdGieC
ipld got block QmY5heUM5qgRubMDD1og9fhCPA6QdkMp3QCwd4s7gJsyE7
ipld got block QmPZ9gcCEpqKTo6aq61g2nXGUhM4iCL3ewB6LDXZCtioEB
ipld got block QmQ5vhrL7uv6tuoN9KeVBwd4PwfQkXdVVmDLUZuTNxqgvm
ipld got block QmciSU8hfpAXKjvK5YLUSwApomGSWN5gFbP4EpDAEzu2Te
ipld got block QmQN88TEidd3RY2u3dpib49fERTDfKtDpvxnvczATNsfKT
ipld got block QmYE7xo6NxbHEVEHej1yzxijYaNY51BaeKxjXxn6Ssa6Bs
ipld got block QmZ9ANfh6BMFoeinQU1WQ2BQrRea4UusEikQ1kupx3HtsY
ipld got block QmdEtks1KYQsrgJ8FXpP1vXygnVHSqnyFTKQ3wcWVd4D2y
ipld got block QmbxHkprr5qdLSK8EZWdBzKFzNXGoKrxb7A4PHX3eH6JPp
Swarm listening on /ip4/127.0.0.1/tcp/4002/ipfs/QmVArb8KVn94EjfxewDtuWy3zgUCXRAq7waLkzchCCgiCA
Swarm listening on /ip4/192.168.1.68/tcp/4002/ipfs/QmVArb8KVn94EjfxewDtuWy3zgUCXRAq7waLkzchCCgiCA
Swarm listening on /ip4/127.0.0.1/tcp/4003/ws/ipfs/QmVArb8KVn94EjfxewDtuWy3zgUCXRAq7waLkzchCCgiCA
ipld got block QmUNLLsPACCz1vLxQVkXqqLX5R1X345qqfHbsf67hvA3Nn
ipfs-unixfs-exporter resolved QmUNLLsPACCz1vLxQVkXqqLX5R1X345qqfHbsf67hvA3Nn
ipld got block QmUNLLsPACCz1vLxQVkXqqLX5R1X345qqfHbsf67hvA3Nn
IPFS node is ready
Waiting 15s...
Stream has been created, waiting for data....
ipfs-bitswap getFromOutside QmaFzTWvp9ktfeC7co1jMCvHQQ2uLpNbEEqdttEEyHVQS3
ipfs-bitswap received block QmaFzTWvp9ktfeC7co1jMCvHQQ2uLpNbEEqdttEEyHVQS3
ipld got block QmaFzTWvp9ktfeC7co1jMCvHQQ2uLpNbEEqdttEEyHVQS3
ipfs-unixfs-exporter resolved QmaFzTWvp9ktfeC7co1jMCvHQQ2uLpNbEEqdttEEyHVQS3
ipfs-bitswap getFromOutside QmT91fmjEBBbVBc774oiR3W8rTv1UZt7iUajRpF4Ri5wWg
ipfs-bitswap received block QmT91fmjEBBbVBc774oiR3W8rTv1UZt7iUajRpF4Ri5wWg
ipld got block QmT91fmjEBBbVBc774oiR3W8rTv1UZt7iUajRpF4Ri5wWg
ipfs-unixfs-exporter resolved QmT91fmjEBBbVBc774oiR3W8rTv1UZt7iUajRpF4Ri5wWg
js-ipfs collected  GO� tT'+��mVڻݭ�ۢ3�A
ipfs-bitswap getFromOutside QmUyyM7CfmosHtKCY6PsAeU7dLsj4gL2iurQgtP17fvSaP
ipfs-bitswap received block QmUyyM7CfmosHtKCY6PsAeU7dLsj4gL2iurQgtP17fvSaP
ipfs-bitswap getFromOutside QmbcpWEkchyeSc5FMkpVkQs6AD3a5nozR3SYy7oyvMFZbN
ipfs-bitswap getFromOutside QmfXApKEQiFpoZwCiEPiKG7r5PqUWey2HHRwHg7XvRrXrg
ipfs-bitswap getFromOutside QmaWGUpyGuVjqax1Kf3ZxzA9Ta2rgXUJyEs7uZJ7reSv9b
ipfs-bitswap getFromOutside QmZDdGHgy8oCNuMmNbS3BdEYysnqBJmeduqck3yrynRSWB
ipfs-bitswap getFromOutside QmdAr7yCgn8KZQr32KaxLwxHFuUbY2sQfqNKPfk494dCky
ipfs-bitswap getFromOutside Qmegd6yHtYP49eLRBq7VKH1SCrEKY9PSZZseaFXJEBniZv
ipfs-bitswap getFromOutside QmNWGfRSL9krg5swbjZZCofc9SBC7oZixJv6WKCDaLRSzv
ipfs-bitswap getFromOutside Qmay5VLWsYQwF1a4z7zB6Y8GGA2iiQTCNSGs7NUjimpDSn
ipfs-bitswap getFromOutside QmbbnxCX4rtC9My2K4B4ZhM2bHHRPQAXnvFeJyEnjUudjx
ipfs-bitswap getFromOutside QmPK8odxBVSKpKkzP3xdM9LyhLC7VcZgtJyqNmfeMdmKgF
ipfs-bitswap getFromOutside QmQhz9yXh2HxrNyy9LosuVbpApEYsf6qV89ca6U8v1vL5b
ipfs-bitswap getFromOutside QmeszXodJVjAQyBikH2heYC7vMoQePQszXdg7LjvTP9MNQ
ipfs-bitswap getFromOutside QmcPYEZcUs1trvkDbpU7YKMmE1vHhWYukSu4e1ptocBnAY
ipfs-bitswap getFromOutside QmesityR3KUQSbxizobSEVrCQEwtp8tqTCi8uAv6iq41ph
ipfs-bitswap getFromOutside Qmdze91CeFM68STkh4WuB2PtUHf13eYGCGyoFsYezN5Pqy
ipfs-bitswap getFromOutside QmQExNEQFfHjHu1GxQqJWAE3QirDLAjf3GAXLGDdD9u9fP
ipfs-bitswap getFromOutside QmZoopANmKFKNMYzXkLMcUUsEXqEZM5JXoKgr3quLpXsJ3
ipfs-bitswap getFromOutside QmQHkU8BLDvsAe3U78FaT8q8dtajY2UoJuTjzshpjVogYT
ipfs-bitswap getFromOutside QmbCe2kSPPA4jpV6B9kweBpFrotHA4ktGyxVNSZDD79bt2
ipfs-bitswap getFromOutside QmcEFwkhm7Jjn2x35qcQQCgNsj6sWDkHXJ5o3VFFXQk46r
ipfs-bitswap received block QmbcpWEkchyeSc5FMkpVkQs6AD3a5nozR3SYy7oyvMFZbN
ipfs-bitswap received block QmfXApKEQiFpoZwCiEPiKG7r5PqUWey2HHRwHg7XvRrXrg
ipfs-bitswap received block QmaWGUpyGuVjqax1Kf3ZxzA9Ta2rgXUJyEs7uZJ7reSv9b
ipfs-bitswap received block QmZDdGHgy8oCNuMmNbS3BdEYysnqBJmeduqck3yrynRSWB
ipfs-bitswap received block QmdAr7yCgn8KZQr32KaxLwxHFuUbY2sQfqNKPfk494dCky
ipfs-bitswap received block Qmegd6yHtYP49eLRBq7VKH1SCrEKY9PSZZseaFXJEBniZv
ipfs-bitswap received block QmNWGfRSL9krg5swbjZZCofc9SBC7oZixJv6WKCDaLRSzv
ipfs-bitswap received block Qmay5VLWsYQwF1a4z7zB6Y8GGA2iiQTCNSGs7NUjimpDSn
ipfs-bitswap received block QmbbnxCX4rtC9My2K4B4ZhM2bHHRPQAXnvFeJyEnjUudjx
ipfs-bitswap received block QmPK8odxBVSKpKkzP3xdM9LyhLC7VcZgtJyqNmfeMdmKgF
ipfs-bitswap received block QmQhz9yXh2HxrNyy9LosuVbpApEYsf6qV89ca6U8v1vL5b
ipfs-bitswap received block QmeszXodJVjAQyBikH2heYC7vMoQePQszXdg7LjvTP9MNQ
ipfs-bitswap received block QmcPYEZcUs1trvkDbpU7YKMmE1vHhWYukSu4e1ptocBnAY
ipfs-bitswap received block QmesityR3KUQSbxizobSEVrCQEwtp8tqTCi8uAv6iq41ph
ipfs-bitswap received block Qmdze91CeFM68STkh4WuB2PtUHf13eYGCGyoFsYezN5Pqy
ipfs-bitswap received block QmQExNEQFfHjHu1GxQqJWAE3QirDLAjf3GAXLGDdD9u9fP
ipfs-bitswap received block QmZoopANmKFKNMYzXkLMcUUsEXqEZM5JXoKgr3quLpXsJ3
ipfs-bitswap received block QmQHkU8BLDvsAe3U78FaT8q8dtajY2UoJuTjzshpjVogYT
ipfs-bitswap received block QmbCe2kSPPA4jpV6B9kweBpFrotHA4ktGyxVNSZDD79bt2
ipfs-bitswap received block QmcEFwkhm7Jjn2x35qcQQCgNsj6sWDkHXJ5o3VFFXQk46r
Stream is receiving data: 4 seconds
done

Here you can see that your code doesn't actually start receiving data until bitswap has received all the blocks in the links from the root block.

After ipfs-inactive/js-ipfs-unixfs-exporter#13:

$ rm -rf ~/.jsipfs && node slow-cat2.js
Instantiating IPFS node
ipld got block QmZTR5bcpQD7cFgTorqxZDYaew1Wqgfbd2ud9QqGPAkK2V
ipld got block QmYCvbfNbCwFR45HiNP45rwJgvatpiW38D961L5qAhUM5Y
ipld got block QmQN88TEidd3RY2u3dpib49fERTDfKtDpvxnvczATNsfKT
ipld got block QmY5heUM5qgRubMDD1og9fhCPA6QdkMp3QCwd4s7gJsyE7
ipld got block QmdncfsVm2h5Kqq9hPmU7oAVX2zTSVP3L869tgTbPYnsha
ipld got block QmPZ9gcCEpqKTo6aq61g2nXGUhM4iCL3ewB6LDXZCtioEB
ipld got block QmQ5vhrL7uv6tuoN9KeVBwd4PwfQkXdVVmDLUZuTNxqgvm
ipld got block QmYE7xo6NxbHEVEHej1yzxijYaNY51BaeKxjXxn6Ssa6Bs
ipld got block QmegvLXxpVKiZ4b57Xs1syfBVRd8CbucVHAp7KpLQdGieC
ipld got block QmciSU8hfpAXKjvK5YLUSwApomGSWN5gFbP4EpDAEzu2Te
ipld got block QmfGBRT6BbWJd7yUc2uYdaUZJBbnEFvTqehPFoSMQ6wgdr
ipld got block QmfGBRT6BbWJd7yUc2uYdaUZJBbnEFvTqehPFoSMQ6wgdr
ipld got block QmZTR5bcpQD7cFgTorqxZDYaew1Wqgfbd2ud9QqGPAkK2V
ipld got block QmegvLXxpVKiZ4b57Xs1syfBVRd8CbucVHAp7KpLQdGieC
ipld got block QmYCvbfNbCwFR45HiNP45rwJgvatpiW38D961L5qAhUM5Y
ipld got block QmY5heUM5qgRubMDD1og9fhCPA6QdkMp3QCwd4s7gJsyE7
ipld got block QmPZ9gcCEpqKTo6aq61g2nXGUhM4iCL3ewB6LDXZCtioEB
ipld got block QmdncfsVm2h5Kqq9hPmU7oAVX2zTSVP3L869tgTbPYnsha
ipld got block QmQ5vhrL7uv6tuoN9KeVBwd4PwfQkXdVVmDLUZuTNxqgvm
ipld got block QmciSU8hfpAXKjvK5YLUSwApomGSWN5gFbP4EpDAEzu2Te
ipld got block QmQN88TEidd3RY2u3dpib49fERTDfKtDpvxnvczATNsfKT
ipld got block QmYE7xo6NxbHEVEHej1yzxijYaNY51BaeKxjXxn6Ssa6Bs
ipld got block QmZ9ANfh6BMFoeinQU1WQ2BQrRea4UusEikQ1kupx3HtsY
ipld got block QmdEtks1KYQsrgJ8FXpP1vXygnVHSqnyFTKQ3wcWVd4D2y
ipld got block QmbxHkprr5qdLSK8EZWdBzKFzNXGoKrxb7A4PHX3eH6JPp
Swarm listening on /ip4/127.0.0.1/tcp/4002/ipfs/QmbWBysea6YL2hzPmE5FeDHVxaiHAX3rXYLTB9yjN7Ma2J
Swarm listening on /ip4/192.168.1.68/tcp/4002/ipfs/QmbWBysea6YL2hzPmE5FeDHVxaiHAX3rXYLTB9yjN7Ma2J
Swarm listening on /ip4/127.0.0.1/tcp/4003/ws/ipfs/QmbWBysea6YL2hzPmE5FeDHVxaiHAX3rXYLTB9yjN7Ma2J
ipld got block QmUNLLsPACCz1vLxQVkXqqLX5R1X345qqfHbsf67hvA3Nn
ipfs-unixfs-exporter resolved QmUNLLsPACCz1vLxQVkXqqLX5R1X345qqfHbsf67hvA3Nn
ipld got block QmUNLLsPACCz1vLxQVkXqqLX5R1X345qqfHbsf67hvA3Nn
IPFS node is ready
Waiting 15s...
Stream has been created, waiting for data....
ipfs-bitswap getFromOutside QmaFzTWvp9ktfeC7co1jMCvHQQ2uLpNbEEqdttEEyHVQS3
ipfs-bitswap received block QmaFzTWvp9ktfeC7co1jMCvHQQ2uLpNbEEqdttEEyHVQS3
ipld got block QmaFzTWvp9ktfeC7co1jMCvHQQ2uLpNbEEqdttEEyHVQS3
ipfs-unixfs-exporter resolved QmaFzTWvp9ktfeC7co1jMCvHQQ2uLpNbEEqdttEEyHVQS3
ipfs-bitswap getFromOutside QmT91fmjEBBbVBc774oiR3W8rTv1UZt7iUajRpF4Ri5wWg
ipfs-bitswap received block QmT91fmjEBBbVBc774oiR3W8rTv1UZt7iUajRpF4Ri5wWg
ipld got block QmT91fmjEBBbVBc774oiR3W8rTv1UZt7iUajRpF4Ri5wWg
ipfs-unixfs-exporter resolved QmT91fmjEBBbVBc774oiR3W8rTv1UZt7iUajRpF4Ri5wWg
js-ipfs collected  GO� tT'+��mVڻݭ�ۢ3�A
ipfs-bitswap getFromOutside QmUyyM7CfmosHtKCY6PsAeU7dLsj4gL2iurQgtP17fvSaP
ipfs-bitswap received block QmUyyM7CfmosHtKCY6PsAeU7dLsj4gL2iurQgtP17fvSaP
ipld got block QmUyyM7CfmosHtKCY6PsAeU7dLsj4gL2iurQgtP17fvSaP
ipfs-bitswap getFromOutside QmbcpWEkchyeSc5FMkpVkQs6AD3a5nozR3SYy7oyvMFZbN
ipfs-bitswap getFromOutside QmfXApKEQiFpoZwCiEPiKG7r5PqUWey2HHRwHg7XvRrXrg
ipfs-bitswap getFromOutside QmaWGUpyGuVjqax1Kf3ZxzA9Ta2rgXUJyEs7uZJ7reSv9b
ipfs-bitswap getFromOutside QmZDdGHgy8oCNuMmNbS3BdEYysnqBJmeduqck3yrynRSWB
ipfs-bitswap getFromOutside QmdAr7yCgn8KZQr32KaxLwxHFuUbY2sQfqNKPfk494dCky
ipfs-bitswap getFromOutside Qmegd6yHtYP49eLRBq7VKH1SCrEKY9PSZZseaFXJEBniZv
ipfs-bitswap getFromOutside QmNWGfRSL9krg5swbjZZCofc9SBC7oZixJv6WKCDaLRSzv
ipfs-bitswap getFromOutside Qmay5VLWsYQwF1a4z7zB6Y8GGA2iiQTCNSGs7NUjimpDSn
ipfs-bitswap getFromOutside QmbbnxCX4rtC9My2K4B4ZhM2bHHRPQAXnvFeJyEnjUudjx
ipfs-bitswap getFromOutside QmPK8odxBVSKpKkzP3xdM9LyhLC7VcZgtJyqNmfeMdmKgF
ipfs-bitswap getFromOutside QmQhz9yXh2HxrNyy9LosuVbpApEYsf6qV89ca6U8v1vL5b
ipfs-bitswap getFromOutside QmeszXodJVjAQyBikH2heYC7vMoQePQszXdg7LjvTP9MNQ
ipfs-bitswap getFromOutside QmcPYEZcUs1trvkDbpU7YKMmE1vHhWYukSu4e1ptocBnAY
ipfs-bitswap getFromOutside QmesityR3KUQSbxizobSEVrCQEwtp8tqTCi8uAv6iq41ph
ipfs-bitswap getFromOutside Qmdze91CeFM68STkh4WuB2PtUHf13eYGCGyoFsYezN5Pqy
ipfs-bitswap getFromOutside QmQExNEQFfHjHu1GxQqJWAE3QirDLAjf3GAXLGDdD9u9fP
ipfs-bitswap getFromOutside QmZoopANmKFKNMYzXkLMcUUsEXqEZM5JXoKgr3quLpXsJ3
ipfs-bitswap getFromOutside QmQHkU8BLDvsAe3U78FaT8q8dtajY2UoJuTjzshpjVogYT
ipfs-bitswap getFromOutside QmbCe2kSPPA4jpV6B9kweBpFrotHA4ktGyxVNSZDD79bt2
ipfs-bitswap getFromOutside QmcEFwkhm7Jjn2x35qcQQCgNsj6sWDkHXJ5o3VFFXQk46r
ipfs-bitswap received block QmesityR3KUQSbxizobSEVrCQEwtp8tqTCi8uAv6iq41ph
ipld got block QmesityR3KUQSbxizobSEVrCQEwtp8tqTCi8uAv6iq41ph
ipfs-bitswap received block Qmay5VLWsYQwF1a4z7zB6Y8GGA2iiQTCNSGs7NUjimpDSn
ipld got block Qmay5VLWsYQwF1a4z7zB6Y8GGA2iiQTCNSGs7NUjimpDSn
ipfs-bitswap received block QmbcpWEkchyeSc5FMkpVkQs6AD3a5nozR3SYy7oyvMFZbN
ipld got block QmbcpWEkchyeSc5FMkpVkQs6AD3a5nozR3SYy7oyvMFZbN
Stream is receiving data: 2 seconds
ipfs-bitswap received block QmcEFwkhm7Jjn2x35qcQQCgNsj6sWDkHXJ5o3VFFXQk46r
ipld got block QmcEFwkhm7Jjn2x35qcQQCgNsj6sWDkHXJ5o3VFFXQk46r
ipfs-bitswap received block QmQhz9yXh2HxrNyy9LosuVbpApEYsf6qV89ca6U8v1vL5b
ipld got block QmQhz9yXh2HxrNyy9LosuVbpApEYsf6qV89ca6U8v1vL5b
ipfs-bitswap received block QmNWGfRSL9krg5swbjZZCofc9SBC7oZixJv6WKCDaLRSzv
ipld got block QmNWGfRSL9krg5swbjZZCofc9SBC7oZixJv6WKCDaLRSzv
ipfs-bitswap received block QmfXApKEQiFpoZwCiEPiKG7r5PqUWey2HHRwHg7XvRrXrg
ipld got block QmfXApKEQiFpoZwCiEPiKG7r5PqUWey2HHRwHg7XvRrXrg
ipfs-bitswap received block Qmdze91CeFM68STkh4WuB2PtUHf13eYGCGyoFsYezN5Pqy
ipld got block Qmdze91CeFM68STkh4WuB2PtUHf13eYGCGyoFsYezN5Pqy
ipfs-bitswap received block QmcPYEZcUs1trvkDbpU7YKMmE1vHhWYukSu4e1ptocBnAY
ipld got block QmcPYEZcUs1trvkDbpU7YKMmE1vHhWYukSu4e1ptocBnAY
ipfs-bitswap received block QmeszXodJVjAQyBikH2heYC7vMoQePQszXdg7LjvTP9MNQ
ipld got block QmeszXodJVjAQyBikH2heYC7vMoQePQszXdg7LjvTP9MNQ
ipfs-bitswap received block QmPK8odxBVSKpKkzP3xdM9LyhLC7VcZgtJyqNmfeMdmKgF
ipld got block QmPK8odxBVSKpKkzP3xdM9LyhLC7VcZgtJyqNmfeMdmKgF
ipfs-bitswap received block QmZDdGHgy8oCNuMmNbS3BdEYysnqBJmeduqck3yrynRSWB
ipld got block QmZDdGHgy8oCNuMmNbS3BdEYysnqBJmeduqck3yrynRSWB
ipfs-bitswap received block QmbCe2kSPPA4jpV6B9kweBpFrotHA4ktGyxVNSZDD79bt2
ipld got block QmbCe2kSPPA4jpV6B9kweBpFrotHA4ktGyxVNSZDD79bt2
ipfs-bitswap received block QmZoopANmKFKNMYzXkLMcUUsEXqEZM5JXoKgr3quLpXsJ3
ipld got block QmZoopANmKFKNMYzXkLMcUUsEXqEZM5JXoKgr3quLpXsJ3
ipfs-bitswap received block QmQExNEQFfHjHu1GxQqJWAE3QirDLAjf3GAXLGDdD9u9fP
ipld got block QmQExNEQFfHjHu1GxQqJWAE3QirDLAjf3GAXLGDdD9u9fP
ipfs-bitswap received block QmbbnxCX4rtC9My2K4B4ZhM2bHHRPQAXnvFeJyEnjUudjx
ipld got block QmbbnxCX4rtC9My2K4B4ZhM2bHHRPQAXnvFeJyEnjUudjx
ipfs-bitswap received block Qmegd6yHtYP49eLRBq7VKH1SCrEKY9PSZZseaFXJEBniZv
ipld got block Qmegd6yHtYP49eLRBq7VKH1SCrEKY9PSZZseaFXJEBniZv
ipfs-bitswap received block QmdAr7yCgn8KZQr32KaxLwxHFuUbY2sQfqNKPfk494dCky
ipld got block QmdAr7yCgn8KZQr32KaxLwxHFuUbY2sQfqNKPfk494dCky
ipfs-bitswap received block QmaWGUpyGuVjqax1Kf3ZxzA9Ta2rgXUJyEs7uZJ7reSv9b
ipld got block QmaWGUpyGuVjqax1Kf3ZxzA9Ta2rgXUJyEs7uZJ7reSv9b
ipfs-bitswap received block QmQHkU8BLDvsAe3U78FaT8q8dtajY2UoJuTjzshpjVogYT
ipld got block QmQHkU8BLDvsAe3U78FaT8q8dtajY2UoJuTjzshpjVogYT
done

You can see that after the PR "Stream is receiving data: 2 seconds" appears mid way through the output, this is because it now can start emitting data before all blocks in the root node have been received by bitswap.

Note I amended your example as follows:

const IPFS = require('ipfs')
const pull = require('pull-stream')
const type = process.argv[2]

console.log('Instantiating IPFS node')
const node = new IPFS()
const hash = '/ipfs/QmaFzTWvp9ktfeC7co1jMCvHQQ2uLpNbEEqdttEEyHVQS3/2.mov'
const streamFunc = type === 'readable' ? node.catReadableStream : node.catPullStream
let dataEvent = false

node.on('ready', () => {
  console.log('IPFS node is ready')
  console.log('Waiting 15s...')
  setTimeout(() => {
    const readyTime = Math.floor(Date.now() / 1000)
    const stream = streamFunc(hash, { offset: 0, length: 5000000 })
    console.log('Stream has been created, waiting for data....')

    const pullable = () => {
      pull(
        stream,
        pull.through(() => {
          if (!dataEvent) {
            dataEvent = true
            const dataTime = Math.floor(Date.now() / 1000)
            console.log('Stream is receiving data: ' + Math.floor(dataTime - readyTime) + ' seconds')
          }
        }),
        pull.onEnd((err) => {
          if (err) throw err
          console.log('done')
          node.stop()
        })
      )
    }

    const readable = () => {
      stream.on('data', (block) => {
        if (!dataEvent) {
          dataEvent = true
          const dataTime = Math.floor(Date.now() / 1000)
          console.log('Stream is receiving data: ' + Math.floor(dataTime - readyTime) + ' seconds')
        }
      })

      stream.on('end', () => node.stop())
    }

    type === 'readable' ? readable() : pullable()
  }, 15000)
})

node.on('error', console.error)

cc @jacobheun @vasco-santos @vmx @achingbrain

@alanshaw alanshaw mentioned this issue Jan 2, 2019
Closed
@alanshaw
Copy link
Member

alanshaw commented Jan 3, 2019

Update - it looks like we're waiting 10s before connecting to the bootstrap nodes which would appear to be the cause of the delay.

@alanshaw alanshaw mentioned this issue Jan 3, 2019
Closed
alanshaw pushed a commit to libp2p/js-libp2p-bootstrap that referenced this issue Jan 3, 2019
fix: discover peers faster
ccae3f1 
Previously we had to wait 10s (by default) **before** initial peer discovery, since the module uses an interval to re-emit discovered peers every 10s. This PR refactors `start` to do an initial discovery of the boostrap peers immediately after it has started (i.e. after the callback has been called).

This addresses the problem where a call to `cat`/`get`/others immediately after the IPFS `ready` event would take at minimum 10s to get content stored on the preload nodes due to the initial delay in discovery.

fixes #85
resolves ipfs/js-ipfs#1706

License: MIT
Signed-off-by: Alan Shaw <alan.shaw@protocol.ai>
@alanshaw alanshaw mentioned this issue Jan 3, 2019
Merged
vasco-santos pushed a commit to libp2p/js-libp2p-bootstrap that referenced this issue Jan 3, 2019
@vasco-santos
fix: discover peers faster (#86)
63a6d10 
Previously we had to wait 10s (by default) **before** initial peer discovery, since the module uses an interval to re-emit discovered peers every 10s. This PR refactors `start` to do an initial discovery of the boostrap peers immediately after it has started (i.e. after the callback has been called).

This addresses the problem where a call to `cat`/`get`/others immediately after the IPFS `ready` event would take at minimum 10s to get content stored on the preload nodes due to the initial delay in discovery.

fixes #85
resolves ipfs/js-ipfs#1706

License: MIT
Signed-off-by: Alan Shaw <alan.shaw@protocol.ai>
@ghost ghost removed the status/ready Ready to be worked label Jan 3, 2019
@lifeBCE lifeBCE mentioned this issue Feb 3, 2019
Closed
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
exp/expert Having worked on the specific codebase is important kind/bug A bug in existing code (including security flaws) P2 Medium: Good to have, but can wait until someone steps up
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fix: discover peers faster libp2p/js-libp2p-bootstrap
2 participants
@alanshaw @lifeBCE