search

ipfs / js-ipfs

IPFS implementation in JavaScript
https://js.ipfs.tech
Other
7.44k stars 1.25k forks source link

datastore-core "Javascript heap out of memory"? #3159

Closed geolffreym closed 4 years ago

geolffreym commented 4 years ago 
<--- Last few GCs --->

[57107:0x1045bb000]  6004964 ms: Scavenge 1905.8 (2050.5) -> 1905.3 (2050.8) MB, 10.7 / 0.0 ms  (average mu = 0.375, current mu = 0.473) allocation failure
[57107:0x1045bb000]  6004981 ms: Scavenge 1906.0 (2050.8) -> 1905.5 (2050.8) MB, 11.7 / 0.0 ms  (average mu = 0.375, current mu = 0.473) allocation failure
[57107:0x1045bb000]  6004995 ms: Scavenge 1906.3 (2050.8) -> 1905.4 (2051.3) MB, 11.5 / 0.0 ms  (average mu = 0.375, current mu = 0.473) allocation failure

<--- JS stacktrace --->

==== JS stack trace =========================================

   0: ExitFrame [pc: 0x1009d4af9]
   1: StubFrame [pc: 0x10095d0e4]
   2: ConstructFrame [pc: 0x10095cc2f]
Security context: 0x3844756c0921 <JSObject>
   3: get [0x3844bb2733b1] [/node_modules/datastore-core/src/keytransform.js:~27] [pc=0x37501b77befd](this=0x3844e1494da9 <InterfaceDatastoreAdapter map = 0x38441c707a11>,0x38447184e101 <Key map = 0x384426c6bc31>,0x3844241004b9 <undefined>)
   ...

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
1: 0x1011c23b5 node::Abort() (.cold.1) [/.nvm/versions/node/v13.12.0/bin/node]
2: 0x10009c059 node::Abort() [/.nvm/versions/node/v13.12.0/bin/node]
3: 0x10009c1b8 node::OnFatalError(char const*, char const*) [/.nvm/versions/node/v13.12.0/bin/node]
4: 0x1001d6b47 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [/.nvm/versions/node/v13.12.0/bin/node]
5: 0x1001d6ae7 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/.nvm/versions/node/v13.12.0/bin/node]
6: 0x10035f8a5 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/.nvm/versions/node/v13.12.0/bin/node]
7: 0x10036113a v8::internal::Heap::RecomputeLimits(v8::internal::GarbageCollector) [/.nvm/versions/node/v13.12.0/bin/node]
9: 0x10035b927 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/.nvm/versions/node/v13.12.0/bin/node]
10: 0x100367cda v8::internal::Heap::AllocateRawWithLightRetrySlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/.nvm/versions/node/v13.12.0/bin/node]
11: 0x100367d61 v8::internal::Heap::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/.nvm/versions/node/v13.12.0/bin/node]
12: 0x100334c47 v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationType, v8::internal::AllocationOrigin) [/.nvm/versions/node/v13.12.0/bin/node]
13: 0x100691928 v8::internal::Runtime_AllocateInYoungGeneration(int, unsigned long*, v8::internal::Isolate*) [/.nvm/versions/node/v13.12.0/bin/node]
14: 0x1009d4af9 Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit [/.nvm/versions/node/v13.12.0/bin/node]
Abort trap: 6
achingbrain commented 4 years ago

Could you give a little more context around this please?

If this happens reliably, can you please take a few heap snapshots while the process is running and share them?

geolffreym commented 4 years ago

Yes, I could. @aphelionz perhaps it could help to understand if it is a problem coming from orbit, since this happens during the replication process...

i have only 1 peer connected, the has been connected maybe for 30 minutes to 1 hour ...

I ll try make the heap snap to support!!

aphelionz commented 4 years ago

Yeah it could be that you're trying to replicate a massive payload over pubsub. If it's determined this is an OrbitDB thing feel free to open an issue over at orbitd/orbit-db and continue the conversation there

geolffreym commented 4 years ago

@aphelionz the thing is that i am not trying replica massive payload, there is just cids gettings saved in log. and opened the error here because it is a datastore-core error https://github.com/ipfs/js-ipfs/issues/3159#issue-653678922

 const db = await orbitdb.log(DB_HASH, {
            overwrite: RECREATE,
            localOnly: false,
            replicate: true,
            meta: {release: 0},
            accessController: {
                write: [orbitdb.identity.id]
            }
        });
let cid = await last(ipfs.add(
      Buffer.from(JSON.stringify(v)),
));
await db.add(cid);

I pinned you because you could help understand if it is a real bug .. sorry if I shouldn't

aphelionz commented 4 years ago

No you're fine! haha, just wanted to make sure we weren't wasting @achingbrain's time :D but it could be that we aren't

geolffreym commented 4 years ago

Cool!! thanks!!

geolffreym commented 4 years ago

@achingbrain I keep doing the memory dump though so far this is the exponential time between entry saved and memory growth pattern while running the code process:

await client.connect(async () => {
            const adminDb = client.db(DB_NAME).collection('...');
            const cursor = adminDb.find({}).limit(0).sort({year: 1}).addCursorFlag('noCursorTimeout', true);
            const size = await cursor.count();

            for await (const v of cursor) {
                let before = +new Date();
                index++;

                let cid = await last(ipfs.add(
                    Buffer.from(JSON.stringify(v)),
                    //{pin: true}
                ));

                // console.log(cid);
                await db.add(cid.cid);
                let per = (index / size) * 100;
                console.log(per);
                console.log('Saving data..');
                console.log('Memory:', (process.memoryUsage().heapUsed / 1024 / 1024).toFixed(2), 'Mb');
                console.log('Time Elapsed:', (+new Date() - before) / 1000 | 0);
                console.log('Created: ', cid.cid.toString());
            }
            await client.close();
            console.log('Closed db..');
        });

May i doing something wrong here? @aphelionz Yesterday before the process failed again memory reached 1930MB As you can see time and memory are constantly growing: 

0.005483658697082694
Saving data..
Memory: 26.41 Mb
Time Elapsed: 0
Created:  QmULHFYppBXvqSkjVXnDEGPhZ8q7TJYFbGi3CY8WeN7SLh
0.010967317394165389
Saving data..
Memory: 25.87 Mb
Time Elapsed: 0
Created:  QmckrDAVvSybQDxQCLPAKCcMEp5CMPe9vEHBnR5XJmq8x6
0.01645097609124808
Saving data..
Memory: 27.00 Mb
Time Elapsed: 0
Created:  QmQ2dsxkajJkNxjRH23JAneuiMinQwamRthdjDMEvY2nyS
0.021934634788330777
Saving data..
Memory: 27.28 Mb
Time Elapsed: 0
Created:  QmQU2bJkyXis5apYyb7xzQpnjp8S3zYnPUhEisyWkhuapS
0.02741829348541347
Saving data..
Memory: 27.41 Mb
Time Elapsed: 0
Created:  QmcpQpuMJskZ11Ucsb9VqTCyHs2MD7rngGM1m3xvGwaWtH
0.03290195218249616
Saving data..
Memory: 27.75 Mb
Time Elapsed: 0
Created:  Qmc9bFPYW5GjTBWo5bbiBWQFBqotiAWxBowR4tmQVE5Z15
0.038385610879578855
Saving data..
Memory: 28.14 Mb
Time Elapsed: 0
Created:  QmNVXtXpbApSTYRszTNv7xHnSzcvcuJw5n9SCtdyTHPQ9D
0.043869269576661554
Saving data..
Memory: 28.32 Mb
Time Elapsed: 0
Created:  QmZ6huqXwjRhZAeW5ChySedcCoFbjwjFnUBLjruCHHJAA2
0.04935292827374425
Saving data..
Memory: 28.42 Mb
Time Elapsed: 0
Created:  QmRFcVLne6MxRNgjjFDWRkSd8wsYq16BQ18ujA4rGhvwmA
0.05483658697082694
Saving data..
Memory: 27.07 Mb
Time Elapsed: 0
Created:  QmZN6mRmWjjoZ89tMUHDhFD9EkQXbfY7GzGiy5YpNLz7Y6
0.06032024566790963
Saving data..
Memory: 27.91 Mb
Time Elapsed: 0
Created:  QmdQ5HRB4aFD99F6uU6uNc8NwZCVZhdqv133k1hLWcHNte
0.06580390436499232
Saving data..
Memory: 28.73 Mb
Time Elapsed: 0
Created:  QmdZwP5nLmRrHQ5QTQwKbYUuKSY2xrrVYoBgkoGjfvDYTW
0.07128756306207501
Saving data..
Memory: 27.67 Mb
Time Elapsed: 0
Created:  Qmd9JtJXoTLaDt3n5Y1AJz6bMCDWAbTiKmUFf7ERpNPdsm
0.07677122175915771
Saving data..
Memory: 26.62 Mb
Time Elapsed: 0
Created:  QmTxhYRy6smhfddh9yEU4VmuUPBoGxdyMy6Wk7Pmzmxxpi
0.0822548804562404
Saving data..
Memory: 28.68 Mb
Time Elapsed: 0
Created:  QmWwgfnwQB9j4AwYgDSmArJVZkTwg5p1s2W62EZPrpcu3h
0.08773853915332311
Saving data..
Memory: 28.56 Mb
Time Elapsed: 0
Created:  QmZVSzwCLCNscUHi3veB2KGSkQkX2Jqvh6r5NFv1TT4pRc
0.0932221978504058
Saving data..
Memory: 27.27 Mb
Time Elapsed: 0
Created:  QmQmjpRqHxBaZbhNwAEi8f5jd9j6EH4H3pDigULDFnjQBp
0.0987058565474885
Saving data..
Memory: 29.94 Mb
Time Elapsed: 0
Created:  QmbWSvWLgcHJ16g8uSxBJ5PtDfkmYy1PQFJKvbgHcfAhvr
0.10418951524457118
Saving data..
Memory: 29.65 Mb
Time Elapsed: 0
Created:  QmR1gb2xRCC9bP2zYkinvoVYRvSzzW8qw5iUWpTEueL3os
0.10967317394165388
Saving data..
Memory: 28.56 Mb
Time Elapsed: 0
Created:  QmYRGHwpP7dXZY77wm2yHsP2kLnuF6cFew3i5NBhAKPv5r
0.11515683263873656
Saving data..
...
.....
Saving data..
Memory: 233.05 Mb
Time Elapsed: 1
Created:  QmcUCDKFqbLVxxmbmut5qAFdTVKHQv7vfXTApnd6BiaWjA
23.108137749506472
Saving data..
Memory: 243.17 Mb
Time Elapsed: 1
Created:  QmTiyZ9WsMbkd9BEYPe4SJoYaoqvdNXxQkQkUAz39zt5pi
23.113621408203553
Saving data..
Memory: 266.17 Mb
Time Elapsed: 1
Created:  QmeP2vLZpGRxHajUNL1Tw9WVqupBSTmQMTbdoEa3gfcFKV
23.119105066900637
Saving data..
Memory: 278.34 Mb
Time Elapsed: 1
Created:  QmR1LJsx25ADqrzivatT8jk2KeQ3aRyZH3gYgWbh9MjfWe
23.124588725597718
Saving data..
Memory: 291.41 Mb
Time Elapsed: 2
Created:  QmXtG7fWfkmgLr5hdMqhk5jkSUoU5ug4dh7qWVMGMzqG36
23.1300723842948
Saving data..
Memory: 299.96 Mb
Time Elapsed: 1
Created:  QmepeVf8VCNMSB37AdHW8YFiQZK1VteHJ8Km8JDDfU2vm2
23.135556042991883
Saving data..
Memory: 313.68 Mb
Time Elapsed: 1
Created:  QmPWqt4ozh5fYZFSjCHFVL4wJ3MwyCEFBctUbydv5dgKTj
23.141039701688968
Saving data..
Memory: 328.82 Mb
Time Elapsed: 1
Created:  QmdPujjnFsFRxnU5Zp14crkHhQHdyxjMK5tpbMzkimBUEk
23.14652336038605
Saving data..
Memory: 342.99 Mb
Time Elapsed: 1
Created:  Qmc8huqSkfbBZ5PxjRHR6HpWwZC8t96tFz531W1Umt6bGL
23.152007019083133
Saving data..
Memory: 357.25 Mb
Time Elapsed: 1
Created:  QmRcLZq2fGte4D3MTDozt8k3WJwXMqXSXhocRSu7kBfdv6
23.157490677780217
Saving data..
Memory: 105.63 Mb
Time Elapsed: 1
Created:  QmPKZQGnuw7j9FBoNvN4JYZxCyygczAXXRh5QtW47cUPxk
23.162974336477298
Saving data..
Memory: 118.27 Mb
Time Elapsed: 1
......
.....
Created:  QmVVspGFX8vNaaLC33rGFDCT9r3L6h6uA8EriUt8m7Ghuq
25.13160780872998
Saving data..
Memory: 366.71 Mb
Time Elapsed: 1
Created:  QmcYRxaoyFqJXy6EctskVPfnvqoct8obQ4JBd3Ttdsx8p5
25.13709146742707
Saving data..
Memory: 99.15 Mb
Time Elapsed: 1
Created:  QmYt3JLHcAGcJcojJ12gvK7281qePH72JRWkUNkRhhchVh
....
....

In some cases the garbage collector manages to clean the memory in others I think that it cannot do it and a memory leak occurs...

Saving data..
Memory: 336.44 Mb
Time Elapsed: 1
Created:  QmVycovLmYw5YakttFikqajX6vGjBvSrN8W2KzEypLmq9w
26.338012722088177
Saving data..
Memory: 346.62 Mb
Time Elapsed: 3
Created:  QmWbfHV9btB6xUcLJQVaoKK7nzJRLjkkVZSrLeTrJVC7ki
26.343496380785258
Saving data..
Memory: 361.18 Mb
Time Elapsed: 6
Created:  QmXViK35V68NJjSvZQUMu74RmKVFntDuseksRuZV5HcZrz
26.348980039482345
Saving data..
Memory: 116.62 Mb
Time Elapsed: 4
Created:  QmUe1pNuqrtXYfvjzrB5oyGHZ2TRxjmupTrETEA7WgRebw
26.354463698179426
Saving data..
Memory: 131.95 Mb
Time Elapsed: 2
Created:  QmcXZEXPGMbaxw9jNsbRvzs8bUnBje4EWDiU63CH914MWg
26.359947356876507
Saving data..
Memory: 144.60 Mb
Time Elapsed: 2
Created:  QmRCZcsF1of4dHABhWeFmTZU9a5bDovY2p3iZZZZiqfEpU
26.36543101557359
Saving data..
Memory: 155.15 Mb
Time Elapsed: 2
Created:  QmY4GhPn7eF52sMy6kB7YcYSpBGXU2nCxc2q2d4gBPHH3M
26.370914674270672
Saving data..
Memory: 107.74 Mb
Time Elapsed: 4
Created:  QmUvi38VFWLzh4kWRp1darPACUvvZ1vLfTGDBsG9gxVmro
26.376398332967753
Saving data..
Memory: 118.58 Mb
Time Elapsed: 3
Created:  QmcQydJQEuSLvUPxqdYAHohbLsKFBbN6kBqyojpgHmQy9x
26.38188199166484
Saving data..
Memory: 129.51 Mb
Time Elapsed: 3
Created:  QmVir29QT3WXVZ1HMzs4QdfPwdYg5un7G1iUQ8cybH588P
26.38736565036192
Saving data..
Memory: 145.09 Mb
Time Elapsed: 3
Created:  Qmf1895MWCr7qWLyy1enRrZdXUx4EBzqbHAyX3id4DdUFP
26.392849309059002
Saving data..
Memory: 159.72 Mb
Time Elapsed: 3
geolffreym commented 4 years ago

@achingbrain this is my customs p2p node settings IPFS.create({libp2p: customFunc, repo: 'source/ipfs' + Math.random(),})

Something important that can i mention is that if I use ipfs-http-api this does not happen "guess because I am using go ipfs" but I mention it precisely because that helps me to know that it is a problem associated with js-ipfs


'use strict'

const Libp2p = require('libp2p')
// const TCP = require('libp2p-tcp')
const wrtc = require('wrtc')
// const Websockets = require('libp2p-websockets')
const WebrtcStar = require('libp2p-webrtc-star')
const Bootstrap = require('libp2p-bootstrap')
const Gossipsub = require('libp2p-gossipsub')
const KadDHT = require('libp2p-kad-dht')
const MPLEX = require('libp2p-mplex')
const SECIO = require('libp2p-secio')
const {FaultTolerance} = require('libp2p/src/transport-manager');

module.exports = (opts) => {
    // Set convenience variables to clearly showcase some of the useful things that are available
    const peerId = opts.peerId;
    const bootstrapList = opts.config.Bootstrap;

    // Build and return our libp2p node
    const p2p = new Libp2p({
        peerId,
        addresses: {
            listen: [
                // '/ip4/0.0.0.0/tcp/4001',
                // '/ip4/0.0.0.0/tcp/4002/ws',
                '/dns4/secure-beyond-12878.herokuapp.com/tcp/443/wss/p2p-webrtc-star/',
                // '/dns4/wrtc-star1.par.dwebops.pub/tcp/443/wss/p2p-webrtc-star/',
                // '/dns4/wrtc-star2.sjc.dwebops.pub/tcp/443/wss/p2p-webrtc-star/'
            ]
        },
        transportManager: {
            faultTolerance: FaultTolerance.NO_FATAL
        },
        // Lets limit the connection managers peers and have it check peer health less frequently
        modules: {
            transport: [WebrtcStar],
            streamMuxer: [MPLEX],
            connEncryption: [SECIO],
            peerDiscovery: [Bootstrap],
            dht: KadDHT,
            pubsub: Gossipsub
        },
        config: {
            transport: {
                [WebrtcStar.prototype[Symbol.toStringTag]]: {
                    wrtc
                }
            },
            peerDiscovery: {
                autoDial: true,
                websocketStar: {
                    enabled: false
                },
                webRTCStar: {
                    enabled: true
                },
                bootstrap: {
                    interval: 60e3,
                    enabled: true,
                    list: bootstrapList
                }
            },
            relay: {
                enabled: true,
                hop: {
                    enabled: true,
                    active: true
                }
            },
            pubsub: {
                enabled: true,
                emitSelf: true
            },
            dht: {
                kBucketSize: 20,
                enabled: true,
                randomWalk: {
                    enabled: true,
                    interval: 300e3,
                    timeout: 10e3
                }
            }
        }
    })

    // p2p.connectionManager.on('peer:connect', (connection) => {
    //  console.log('Connection established to:', connection.remotePeer.toB58String())  // Emitted when a new connection has been created
    // })
    //
    // p2p.on('peer:discovery', (peerId) => {
    //  // No need to dial, autoDial is on
    //  console.log('Discovered:', peerId.toB58String())
    // })

    return p2p
}