Follow-up to read stream lag

[lifeBCE]

• Version:
  0.34.2

• Platform:
  Darwin MacBook-Pro.local 16.7.0 Darwin Kernel Version 16.7.0: Thu Jun 15 17:36:27 PDT 2017; root:xnu-3789.70.16~2/RELEASE_X86_64 x86_64

• Subsystem:
  Potential Bitswap but not sure

Type:

Bug

Severity:

Medium

Description:

This is a follow up to #1706

I am still seeing an average 8 second delay when streaming blocks before the stream will emit its data event only if the length argument is omitted or large.

Steps to reproduce the error:

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.catReadableStream : node.catPullStream;
let dataEvent = false;

node.on('ready', () => {
  console.log('IPFS node is ready');
  const readyTime = Math.floor(Date.now() / 1000);

  // This length value produces the 2 second delay from original issue
  // const stream = streamFunc(hash, { offset: 0, length: 5000000 });

  // This will produce the average 8 second delay but so will any large value of length
  const stream = streamFunc(hash);
  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);
})

Note: May want to change the hash value to something in your test env.

Being a stream function, my expectation is that the size of the file or bytes being requested should not have an impact on the time to initial data event trigger. Worth mentioning that I am using go-ipfs as the websocket bootstrap server behind nginx.

[alanshaw]

@lifeBCE the callback you give to pull.concat is called only when ALL of the data has been recieved. Do you see the same problem using pull.drain instead?

[lifeBCE]

I have updated the test code to use pull.through and get the same 8 second delay. I'll have to dig into the syntax for pull.drain as it does not seem to be a direct replacement for pull.concat or pull.through.

Worth notiing that I don't think any solution waits for the entire file to download as the test logic continues to download the large file after it reports that the event has been triggered. Also, my use case is the readable case. Does stream.on('data', .... wait for the entire file as well> Test runs suggest that it does not wait either but not sure.

Here is the latest POC that shows an 8 second delay using either pullable or readable.

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.catReadableStream : node.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.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()
      })

//      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);
})

[alanshaw]

@lifeBCE I'm getting this:

$ node slow-cat3.js 
Instantiating IPFS node
Swarm listening on /p2p-circuit/ipfs/QmSeJDTNXyVtGCKyjZ79HGknuLaEdttm7VreA1cwefNa39
Swarm listening on /p2p-circuit/ip4/127.0.0.1/tcp/4001/ipfs/QmSeJDTNXyVtGCKyjZ79HGknuLaEdttm7VreA1cwefNa39
Swarm listening on /p2p-circuit/p2p-websocket-star/ipfs/QmSeJDTNXyVtGCKyjZ79HGknuLaEdttm7VreA1cwefNa39
Swarm listening on /ip4/127.0.0.1/tcp/4001/ipfs/QmSeJDTNXyVtGCKyjZ79HGknuLaEdttm7VreA1cwefNa39
IPFS node is ready
Stream has been created, waiting for data....
Stream is receiving data: 2 seconds

$ cat node_modules/ipfs/package.json | json version
0.34.4

[alanshaw]

Scratch that, I AM seeing the issue when starting with a fresh repo.

[lifeBCE]

@alanshaw Are you using the same hash? Deleting local cache?

$ rm -rf ~/.jsipfs && node slow-stream.js
Instantiating IPFS node
Swarm listening on /ip4/127.0.0.1/tcp/4002/ipfs/Qman7fPwX1CmUy21qyhSRparyi5dcpvfB1qL75jzDAvh5z
Swarm listening on /ip4/192.168.2.4/tcp/4002/ipfs/Qman7fPwX1CmUy21qyhSRparyi5dcpvfB1qL75jzDAvh5z
Swarm listening on /ip4/127.0.0.1/tcp/4003/ws/ipfs/Qman7fPwX1CmUy21qyhSRparyi5dcpvfB1qL75jzDAvh5z
IPFS node is ready
Stream has been created, waiting for data....
Stream is receiving data: 7 seconds


$ rm -rf ~/.jsipfs && node slow-stream.js readable
Instantiating IPFS node
Swarm listening on /ip4/127.0.0.1/tcp/4002/ipfs/QmeinGbJ6WCsL3p7XPeNBEJWo5BBkQb4vvFRNC3Qie3f3o
Swarm listening on /ip4/192.168.2.4/tcp/4002/ipfs/QmeinGbJ6WCsL3p7XPeNBEJWo5BBkQb4vvFRNC3Qie3f3o
Swarm listening on /ip4/127.0.0.1/tcp/4003/ws/ipfs/QmeinGbJ6WCsL3p7XPeNBEJWo5BBkQb4vvFRNC3Qie3f3o
IPFS node is ready
Stream has been created, waiting for data....
Stream is receiving data: 7 seconds

I am on 0.34.2 so I'll give 0.34.4 a try but didn't notice anything between the two that might account for the issue.

[achingbrain]

Does this still happen with 0.41.0? Most of the supporting code has been completely rewritten.

[achingbrain]

Closing as this issue is very stale.