IPFS IPFS Camp 2022, 3 Nov 2022

Previous Meeting Next Meeting

⏯

youtube image

►

From YouTube: Debugging js-ipfs and js-libp2p Like a Pro - Alex Potsides

Description

The lead maintainer of js-ipfs and js-libp2p will share tips and tricks for debugging js-ipfs

A

So my talk is debugging JS ipfs, like a pro that was the title of the talk, uh I added like a pro wrestler. This it's made a lot of sense to me at like 2 A.M when I was writing these slides, yeah I'm, not sure how far I can stretch this analogy, but we'll see um because I yeah so I mean obviously there's like the grappling aspect. It's hard. There's no guarantee of success. uh Also, like so I, grew up in the UK uh like in the 90s.

A

There wasn't. There was only terrestrial TV at the time and then this thing came along called Sky TV, which is like television through your satellite amazing. It's like living in a future and one of the things that was on Sky TV was was WWF wrestling and uh yeah like as like 10 or 12 year old me, I'm, not quite sure, on the actual time scale that it just seemed impossibly exotic um and now I I lose I, lose so much time. Reading biographies and the stories of what happened to all these.

A

These people on Wikipedia, um but all the actual wrestling shows. It always strikes me that it's more like a soap opera uh than actual sport I mean obviously a sport, there's incredible uh physiques and that kind of stuff, but but the actual things that are happening is like a soap opera and like any any soap opera. There's only was it there's a famous start, there's like six or eight plots to any soap opera um and they just get repeated endlessly, and then you yeah, um and when you're debugging things usually there's.

A

You know, there's a few things that were always bad. Like string, concatenation, regular Expressions, um like memory copying that kind of stuff, so usually you can find like you're like yeah. This was probably it, but also the one thing about debugging that doesn't apply to soap operas is like measurement is super important. It's really easy to go down rabbit holes chasing the wrong thing, so you must measure everything measure, absolutely everything.

A

um Yes, so uh who am I? I'm Alex, bossidis, aching brain on the internet, um I maintain uh I'm on the IP stewards team for protocol Labs I maintain JS, ipfs, Json P2P.

A

um A lot of the JS stack I am hiring. I would like to not maintain all these things all the time I would desperately like some help. So please come and talk to me if, uh if you'd like to join the team, so.

B

We're going to cover some things.

A

um Logging debugger metrics gonna go back to logging briefly and then like Prometheus to actually get some stats out and then hopefully are going to fix a problem um streaming. I can replicate it, so logging is um yeah. So so we have a lot of logging in Js ipfs. It's all based on this, this little PCP logger package, which really is just using the debug module um it's behind this extra package, because the bug is not esm yet so at some point we can.

A

We can switch out without having to change all the code everywhere, to use an esm module to get profitable for Sky, Park and and all these like future Tech future Tech things. So it's a very simple API.

A

You just have the name of the module, uh the name of the subsystem, and you have three three ways of cooling: it. You get the the regular log, you get a trace log and you get an error log um and we'll see how we can pull these out individually later.

A

um To enable the logging, it's very easy, uh there's just a um an environmental variable uh debug and you pass in a pattern. This also works in browsers. You just set the local storage variable, with the caveat that you know with the node version, if you control C, and then you start again with just jsrpfs, you won't see the logging in the browser.

A

You definitely will so if you set it to be something, that's too uh verbose and your browser catches fire, it will catch fire as soon as you restart the page uh reload, the page. Sorry so um be careful and you have lots of options, so you can have wild cards.

A

The second one will give you everything, it's very noisy um and then you can have multiples and you can remove things. You can do individual uh things. It's going to start up. It's like great! Now what it's a completely black box I have no idea what's happening, so I can stop. It.

B

Start again to bug to bug everything all the things yeah, it's like it's too much.

A

Definitely too much so we can. We can stop and we can have a look at what's going on in here. So uh we can see. We've got like the pier store, it's doing things mdns is doing things.

A

You know more in business, things more pistol. You.

B

Can just see that some of these components.

A

Are very noisy nplex and Caribou noises or implexes like printing out the different messages that are coming in these are very, very noisy. So, let's just look at like one thing. So if we just look at identifier, for example, we can just do start it up again and now we'll only see messages from identify, which is probably uh you know, an interesting thing to choose, given that I need some network connectivity in order to actually uh run identify, and obviously this is conference Wi-Fi. So.

A

Anyway, you have to say my word for that one, okay anyway, so too,.

B

A

Anyway, I'm going to move on so uh yeah, so you can you can uh you can have multiples? You can have individual components. uh This is my favorite. One uh is just to basically remove mobile stream select and then remove all the trace logging because it's very, very, uh very noisy. It would be interesting to have a way that doesn't turn on Trace logging by default, but that's the debug API.

A

So yeah, so a more concrete example. Here we go starting up showing all the things. Okay, that's Logan. What else so this is a! This is more like General uh how to debug node things. um This is so this is the debugger um you. You can obviously do this in the browser too, and the browser is super. Easy. You just pop open. The developer console stick a breakpoint in and you're away. You have to debug it all the time and no you don't so.

A

You've got uh the inspect command that you can start the node with which will create a port and you can connect to it using the debugger, that's in every version of Chrome. So if I.

B

If I start node options, inspect cheers ipfs demon.

A

So now I see a message: the debugger is listening so now I can open in Chrome.

B

A

Want to show the URL, so the URL here you're gonna, have to take my word for it. It's way too far away. If you want to read it, but it's the Chrome colon inspect and then you'll see that we have a remote Target that we can debug. So I can connect to it like this in the in the console, I see debugger attached and suddenly here, I am so I'm. Now I can now debug things which is fantastic, so I can stick break points in here.

A

Obviously, there's a lot of code um and we can inspect what's going on. That's very useful. What? If, what? If my, uh what if I forgot to start it uh well I'm back, so that's useful in the the uh Json versus started up now, but uh what, if you know you wanted to start from the beginning of the the process? So you want to put breakpoints in maybe you're debugging the startup process.

A

uh You obviously can't connect to it quickly enough, so you can use the inspect work, uh break ing for debugger to disconnect okay disconnect, so the other one that you can use is inspect work.

A

So now it's attached to debugger, it's pulls the process, so I can go back to Chrome.

A

The target is turned up and I can log on to the debugger, and now it has stopped before the very, very first import, so now everything's suspended I can I can go through the source tree I can stick things in and debug where I want to, obviously, because uh um if you're debugging Liberty to P like this, because it's on our typescript, you need to go and put the breakpoints in the compiled JavaScript rather than the typescript I'm sure there's a way around it.

A

I Source, Maps I've, just to work very well anyway, so I can go into the core somewhere. Maybe the startup- and this is the.

B

A

So jsip versus uh all esm and not uh not typescript, so I can go into the source, components, I, don't know index and just stick a breakpoint in in our Constructor for ipfs and then just click.

B

A

It will there we go so now. It's paused, because Jerry's daughter.

A

So I can look at the scope. I can see, the variables are going to be defined. I can see all kinds of things. This is very useful. I can step over things. This is a bugger. The buggers are wonderful. It's like the Swiss Army knife of uh tools, I can't I, don't know what the wrestling analogy would be for this I. Don't think there is one so I told you. I was going to try and stretch that analogy as far as possible, anyway.

A

um Okay, so that's the debugger. So what if you've got a running process? And you want to debug it, but you, but you didn't specify those arguments, no problem, you send a Sig user, one signal to the PID of jsipfs and we can do exactly the same thing.

B

A

If I, just let that one go, disconnect the debugger and kill it and I'm going to take two of these big and big big, and so here, I'm.

B

Going to do this.

A

Run run hooray and then in this window, I'm just going to do a bit of jazz ipf. Oh sorry, I'm going to do a bit of itfs because it renames the process, you'll notice, the ipfs and not JS ipfs, because why not um so we have the PID there so I can just do, kill. Obviously, don't forget the dash, if you just desig user, one and that'll actually just kill the process entirely. No, no!

A

So there we go so now the debug is listening. It's appeared in a inspector again and I can open the debugger um and we're away very useful.

B

A

Metrics, sorry, this is great, uh but what if I mean we want like to be able to see things like CPU usage memory usage, uh there's a whole bunch of interesting metrics that ipfs exposes and live P2P, but only if you set this ipfs monitoring uh environmental variable because the metrics are not free.

A

um It saying this variable will configure a matrix object within lipitv itself. That is then shared by ipfs to add extra stats around like bit, Swap and and all kinds of stuff, but you must specify the the environmental variable, ipfs monitoring, true uh something else. This does is it it creates a uh so the way Prometheus pulls the stats out is that it will create an endpoint that the client can call. It also enables another endpoint that lets you dynamically change, uh the debug level for the debug login, which is incredibly useful.

A

B

Disconnect the debugger.

A

Kill the thing uh ipfs monitor, ing.

A

True, there's I prefers demon.

B

A

Next, yeah logging, okay, fine! So here we go so it's not! Our we've got the monitoring and then, if I hold on there, it is so we can now now this is running. There's an extra endpoint, that's running um you can, if you're a hardcore use, Curl or wget or whatever to then like, send a request.

A

It's a post request, uh the magic URL debug and then, but you have to escape all the colons and that kind of thing uh like I, don't hate myself, so I'm not going to do that, I'm going to use an app to do it so I'm, just using this uh rest client.

A

This is uh this is just a uh just. A simple client called insomnia that I use to make requests because I can just type um I can just type the the argument in.

A

No, it doesn't want me so so I just typed this bit here. The question was: do I still have to URL encode? If I'm using this app? No I? Don't uh it does it for me, so it just it generates the URL that it's going to send it to so you could then actually take this and paste it into the terminal if you wanted um but yeah, so you can just type the thing.

A

So, if I send the request and now suddenly that my console has gone mad and suddenly no, the log level has changed, which is useful.

A

Sorry before I change it to like yeah, you go back to doing a single component, so, like TCP, send now I'm only going to see TCP messages.

A

um This is also interesting because we see lots of read timeouts where we're trying to connect to remote nodes and they don't respond for whatever reason.

A

Okay, so what else so we have exposed a Prometheus endpoint uh Prometheus is fantastic. It lets you get nice graphs. It also means that we can now do nice things in grafana, like all these wonderful dashboards, that everyone sees.

B

You can use them with jsrpfs there's.

A

Loads of like fun metrics in there, so uh Prometheus yeah I'm not going to go into too much detail about Prometheus. You can go to the website download it super easy. uh You just configure a job um with the you just ensure that your config file has scrape configs with uh the right metrics path and host and the port number. And then you just start Prometheus with the um uh with the with the config file, which is great, uh and it looks a bit like this.

A

uh Wherever it's gone, yeah can't update no don't reinstall Chrome well, not now, um where did I put it um yeah? So there we go.

A

So this is perimeters, also doesn't very much so we have lots of useful queries in here. So, for example, here we just have like all the memory usage by node um gives us a nice graph I'm going to change it to just be very short, so we have our node startup spikes. The memory goes right down to something reasonable, like the green thing is the interesting one. Is the amount of Heap size that we've we're using um so above that there's the the total Heap and then uh the total memory usage from node.js.

A

So obviously the operating system is going to vary this. We can only really affect this one, which is the amount of heat use which is like you know, just under 200 megabytes, which is not too bad for a JavaScript application.

A

um So there's some interesting queries. You can run so like there's no nice and easy way of pulling CPU usage out Prometheus, but you just use this fantastic little function to do it. um You see the memories, so the node memory usage is actually a custom. One. That's added by jsrpfs that just like takes all the node stats together and puts them on one graph. It's quite useful, I find and we have some- we have some specific Lupita P ones.

A

So, the like the number of connections you can instate the Specter bit Swap and we're adding more so one thing that's happening like specifically with uh chainsafe and load star, is they're very, very interested in the performance of like the TCP transport. So there's a whole bunch of stats being added around that.

A

Also gossip sub, like the state of the mesh, the the number of retries, like the scores of various peers loads of metrics around that uh with they've, actually they've, actually implemented their own metrics Gathering, because the the default load p2p1 was lagging a little bit and they needed it like yesterday. But it's very much on the roadmap to try and bring all those together so that you can get really good stats out of all the the very uh high like contention resources within your ipfs node yeah. So so we can see in here.

A

We have you just like you, can just type Liberty to p and you've got all kinds of interesting things. So you've got the the DHT routing table sizes. We've got some nplex stats. uh A number of listeners that we have for transports um interesting. Other interesting ones are like the so the active handles. So this is the number of uh essentially the number of sockets that you're holding open.

A

So you would expect this to track the number of active connections that you have if you're, if the handles go way above the number of connections or they keep growing, then you've got a leak somewhere and you need to find it, um which is like yeah, more typical in your average memory leak.

A

So this is the number of connections we have obviously we're in a conference zone. So we're gonna see some interesting things, so I haven't actually connected to anyone, but I have 63 outbound connections, so I'm dialing appears that I'm ambiently, discovering um yeah Prometheus is very useful. Gives you a great window into what's going on right? So so it's been very dry so far, but we're going to try and do something interesting now. So we're going to put it all together, um so something I'm quite interested in is that a little Spike at the beginning.

A

We saw it in the memory so the beginning of your stars. Here's like the CPU, so this one's interesting. So there's this there's a spike that goes down and then we do nothing for a bit and then we go back up something worth investigating, but I'm quite interested in this little Spike here that when we start so obviously, when you start a note up, it's doing nothing, that's doing something so you're going to start uh it's gonna I mean the CPU is gonna Spike, because you weren't doing anything and now suddenly you're doing something.

A

But let's see what what's it actually doing. So, if I, if I kill my node uh and I'm going to start it in debug mode and take a CPU profile.

A

Kill all the things I'm gonna kill it with Force.

B

A

For the interests of there we go again he's done it great cool, so I'm gonna do.

B

A

True I'm gonna do deep node.

A

Options inspect Burke.

A

Connect to the debugger start, the profiler start taking CPU profile.

B

Go back to the sources. ah Does this stuff ever work.

A

It has started for me, that's great! That was interesting, so I've connected it earlier, so I've connected a CPU profile, and that has started it for me, which is good. A demon is ready. So now we're going to look at the CPU profile, very small, it's very small.

A

So in the CPU profile we have two measurement sales time and total time. So these are. This is the amount of time that we spend in all these functions. Self time is the amount of time taken for a function to execute but minus the time when you call out to other functions.

A

So if you have one function that you think is very slow because it's doing something like looping over a bunch of arrays or something like that.

A

It's going to it's going to slow down in self-time total time is sometimes more useful because you can see how, like you, can kind of descend into the stack and you can see where the CPU time is taken up and you get more of an idea of where, like the the components that are the bad ones and that have the that have the the dependencies that are slow because often the code that is slow is not your code. It's often is often other code that you're calling.

A

So if we go so we can look at we've sort it by the time taken. I can look at a callback trampoline on message, so this is interesting. So here we go so it's a datagram, so this is not TCP. This is uh this is going to be UDP, something that's happening so already, so we start thinking right what what do we use for UDP? So there's no quicker node yet, um but we do other things in the UDP. So some of the things that we do is uh like mdns is all UDP events.

A

Oh look, there's mdns, that's interesting! So, what's going on here, so we're making our DNA so we'll use npns, for so we use it for local Discovery on the network, so we're obviously in this Zone I mean how many laptops are there in here. I can see at least like seven or eight node, 10 15, and then imagine all the other people around uh there's a lot of laptops.

A

There's gonna be a lot of mdns going on, um so we can go further in and get addresses encapsulate, so we can obviously click through and see what's happening. So, if I look at this, where am I I'm in I'm in multi other, oh that's interesting, so I can dig down further. Obviously the percentage is getting smaller and smaller. We go down string. It will string to bite hello, so we're doing something with a string like what do we do with strings?

A

We have to parse them. What do we use to pause strings? Oh no, convert to bytes IP to bytes to bytes is ip4. Oh, is Matt oh match. What do we match on I? Don't know. Is it regular expressions?

A

Have we got a really slow, regular expression in here somewhere.

A

I think we might do so.

A

I think it's so you don't dial rubbish like a string that isn't a regular expression so anyway, so now, where are we we're in? This is much, and here we are um oh look as a regex, oh cool. So so what we found is we've drilled all the way down. We found that there's there's a slow, regular expression somewhere in our stack, um it's around multi-adders and like parsing multi-adders from strings um and yeah. So if you actually look at, if we actually look at oh, let me get a window.

A

This is an interesting thing because it actually came up uh in.

B

Multi-Form, that's multi-adder.

A

um I, don't know what am I doing this on conference Wi-Fi anyway. This came up recently because lodestar actually noticed that there I must say recently I mean like yesterday, because loadstar actually noticed uh I'm gonna switch onto my phone.

A

um Yeah, at least I noticed that they were consuming an awful lot of CPU usage, pull requests, so they yeah, so they found they found that we're using an awful lot of CPU usage in this in load store. So they did. They did a very similar, very similar um investigation, and so they found actually in this is IP. You can see it. It was actually using 9.75 of CPE time um because they, they obviously have very high traffic nodes and so there's a lot of pausing of this stuff.

A

um So that is a that is a terrible, terrible start and what they've done is they've taken right, so they've they've, measured it and they've identified the bottleneck and what they've done is they've taken they've, actually taken uh all the radio Expressions out, they've written a uh a new regular expression.

A

Sorry, a new IP address, parser, that's actually based on the rust implementation uh and it's between 30 and 300 times faster than his IP, which is great and here's a here's, a PR that from them very helpful which swaps it out in multi-adder, which is going to solve our performance problem. This is the power of Open Source. So I'm uh I'm just going to merge that one.

B

And uh yeah thanks.

A

That's it there we go so we fixed our performance problem. um Someone else fixed it, which is like it's. The key to successful software development is making your problem someone else's problem and uh they've done it, which is great. That's it that's the talk.

A

um Thank you very much for attending.