Debug Nodebb load

<baris>

@damian-gądziak I believe performance should be better check your package.json for templates.js, we switched from that to benchpress which is alot faster. There were alot of cache improvements on later versions as well.

Damian Gądziak

@baris Performace is much much better for guests, but other hands worse for signed in users.
We have just upgraded nodebb from 1.5.1 to 1.8.2.

A guest visitor is able to get HTTP response from the homepage in 100-200ms, where signed in user need to wait for about 4-5s.
We have already 7M topics (not 1M) and probably some redis queries are not optimized

<baris>

@damian-gądziak Is your forum public? Is the hompage loading a list of categories? What is the size of the payload when you load /api for guests vs registered users?

Damian Gądziak

@baris we are not loading categories at home page, there is even no request to nodebb /api endpoint (as a guest).
Yes, it's public (https://urstyle.com) you can compare page speed as a guest and signed in user.
There is 7M topic because we have about 7M subpages connected via nodebb-plugin-comments

Damian Gądziak

There is also one more application entry via urstyle.pl (this domain has turned ON varnish for static files), urstyle.com is serving statics via nodebb as now, but it seems to not be a clue of the problem

<baris>

Not sure how your homepage is rendered, since both guests and registered users get the same response in /api, I would check the code that you have for registered-users and figure out why it is taking longer than guests. Number of topics in the database should not effect the load speed unless there is some code that is doing a lot of processing on those topics to load the homepage.

Damian Gądziak

@baris it seems that signed in user need some data from redis, but after nodebb upgrade redis stats looks not so good,
total operations increased from 9M to 25M per minute
CPU load from 40% to 100%
so yeach, that's the problem

<baris>

If you have custom code to load the homepage take a look there and see if anything is being loaded in a loop. You can post here if you can maybe we can spot some inefficiency.

Damian Gądziak

@baris at redis monitor I see a lot queries like:
"zscore" "uid:41843:followed_tids" "990614"

What they mean ? User #41843 watching topic #990614 ?

Damian Gądziak

So, interesting thing.
I have disabled execution of this query

"zscore" "uid:41843:followed_tids" "990614"

by hardcoding response of "Topics.filterWatchedTids" function (always return []).

Redis and CPU load decreased of about 50%

Next query on my list is:

(integer) 369411

(integer) 1524255134
3) (integer) 291408
4) 1) "zrevrangebyscore"
2) "topics:recent"
3) "+inf"
4) "1524082333364"
5) "WITHSCORES"
6) "LIMIT"
7) "0"
"-1"

which took about 0.3s to run and basically should be cached

<baris>

@damian-gądziak Maybe you can try to debug by adding this in that function console.log(tids.length, uid, new Error('test').stack);

	Topics.filterWatchedTids = function (tids, uid, callback) {
                console.log(tids.length, uid, new Error('test').stack);
		async.waterfall([
			function (next) {
				db.sortedSetScores('uid:' + uid + ':followed_tids', tids, next);
			},
			function (scores, next) {
				tids = tids.filter(function (tid, index) {
					return tid && !!scores[index];
				});
				next(null, tids);
			},
		], callback);
	};

I am guessing the function is called by a huge amount of tids, so the next step would be to find out why and from where.