I've put this server under taxing I/O load while injecting articles over the last and never saw this behavior until expireover had been running for a little over 4 hours. Any ideas?<snip>
For the past week I've been pull articles into a news server running FreeBSD >and INN 2.7.0rc1, and got to a stopping point after adding a few hundred >gigabytes to the spool, so I decided to run news.daily since I hadn't since >this endevor began.
I understand during certain portions of the news.daily process the server gets >paused. However, I am noticing very strange behavior when the server claims it >is not paused (according to logs), but while expireover is running.
INN is unresponsive to ctlinnd commands for ~5 minutes and suddenly becomes >responsive, the upstream innfeed process (on another VM) reports a >non-responsive connection during these periods. NNRPd is responing normally >for the most part, I can AUTH, issue GROUP, BODY, and similar commands, but >when I issue a POST I get no response from the server until my connection >times out.
I can't find anything useful in the logs as to what is happening while INN is >not responding, nor do I see any other underlying OS or I/O issue. The >expireover process is using 100% of one CPU core, and quite a bit of I/O, but >not enough that should cause this kind of unresponsiveness. The OS is >responsive and other applications/daemons on the box respond as expected so I >don't see a server-wide performance problem.
I've put this server under taxing I/O load while injecting articles over the >last and never saw this behavior until expireover had been running for a >little over 4 hours. Any ideas?
top:
last pid: 53975; load averages: 1.22, 1.20, 1.15
up 4+20:06:35 22:59:56
75 processes: 2 running, 73 sleeping
CPU: 2.1% user, 0.0% nice, 10.6% system, 0.0% interrupt, 87.3% idle
Mem: 160M Active, 6103M Inact, 62M Laundry, 8652M Wired, 905M Free
ARC: 5910M Total, 3785M MFU, 1455M MRU, 912K Anon, 91M Header, 578M Other
3725M Compressed, 8526M Uncompressed, 2.29:1 Ratio
Swap: 2048M Total, 2048M Free
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND 8478 news 1 103 0 66M 42M CPU5 5 434:17 99.86% expireover
55548 root 1 20 0 32M 8916K select 3 3:45 0.09% snmpd >53975 root 1 20 0 14M 3440K CPU3 3 0:00 0.05% top >31561 root 4 20 0 49M 18M select 0 6:12 0.05% vmtoolsd
53913 news 1 24 4 37M 16M sbwait 6 0:00 0.03% nnrpd >29975 root 1 20 0 13M 2292K select 1 4:26 0.01% syslogd >-----
iostat:
root@spool1:/var/log # iostat
tty da0 cd0 pass0 cpu tin tout KB/t tps MB/s KB/t tps MB/s KB/t tps MB/s us ni sy in id
1 728 43.4 222 9.4 17.2 0 0.0 0.0 0 0.0 6 0 6 0 88
-----
systat:
/0 /1 /2 /3 /4 /5 /6 /7 /8 /9 /10
Load Average ||||||
/0% /10 /20 /30 /40 /50 /60 /70 /80 /90 /100
root idle XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
root idle XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
root idle XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
news expireover XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
root idle XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
root idle XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
root idle XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
root idle XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
root idle XXXXXXXXXXXXXXX
-----
Cheers,
Jesse
How is your expire configuration configured?
On Jun 23, 2022 at 11:05:31 PM CDT, "Jesse Rehmer" <jesse.rehmer@blueworldhosting.com> wrote:
<snip>
I've put this server under taxing I/O load while injecting articles over the >> last and never saw this behavior until expireover had been running for a<snip>
little over 4 hours. Any ideas?
So after killing the few nnrpd processes that were running off, the performance issue has resolved. There were only two active processes, my reader, and one from UZANTO-RETO (<https://www.uzantoreto.com/>) who scans my server. They make slow requests and were not hammering the box, and my connection is idle. The expireover process is still running same as before, but article delivery and other commands are good.
As soon as I start NNRPd and make a connection the problem returns even though
I am doing nothing. WTH.
-Jesse
There was an 18-minute gap in innd activity according to the news.notice
log where it was completely unresponsive (no response on port 119, no response to ctlinnd commands, etc.). During this period truss did not
output anything for innd or its children (unfortunately I wasn't
attached when the condition began). When things sprang to life what I
saw with truss looked like history or overview read/writes and articles started flowing.
What I'm seeing in the logs is the period of unresponsiveness ends with
innd logging its stats. There are some interesting entries after that,
such as "SERVER cant sendto CCreader" and I have a lot of "Connection
reset by peer" and "broken pipe" messages. The latter two appear
frequently for a few minutes and subside.
My apologies, I did leave out some critical details - I am using tradspool/tradindexed.
Additional observations:
- While innd is unresponsive, nnrpd was happily serving clients and the
only indicator something was amiss from the client perspective is
posting would fail with a timeout reported by the client.
Jesse Rehmer <jesse.rehmer@blueworldhosting.com> writes:
My apologies, I did leave out some critical details - I am using
tradspool/tradindexed.
Do you by chance have a really large group that would take a long time to expire? It's been a while since I wrote the locking strategy for tradindexed, but expiring a group locks it for write and receiving an
article in the same group will also attempt to lock it for write, and innd
is single-threaded. So if you receive an article for a group while that group is being expired, innd will wait for the lock until the expiration
of that group finishes. If that group is extremely large, this could well take ten minutes.
Jesse Rehmer <jesse.rehmer@blueworldhosting.com> writes:
There was an 18-minute gap in innd activity according to the news.notice
log where it was completely unresponsive (no response on port 119, no
response to ctlinnd commands, etc.). During this period truss did not
output anything for innd or its children (unfortunately I wasn't
attached when the condition began). When things sprang to life what I
saw with truss looked like history or overview read/writes and articles
started flowing.
What I'm seeing in the logs is the period of unresponsiveness ends with
innd logging its stats. There are some interesting entries after that,
such as "SERVER cant sendto CCreader" and I have a lot of "Connection
reset by peer" and "broken pipe" messages. The latter two appear
frequently for a few minutes and subside.
This feels like lock contention. What overview method are you using? I tried to find that in the thread but may have missed it.
I agree, but unfortunately lack the technical knowledge to understand better why this would be happening, and what if anything I could do to resolve it.
My apologies, I did leave out some critical details - I am using tradspool/tradindexed. Additional observations:
- While innd is unresponsive, nnrpd was happily serving clients and the only indicator something was amiss from the client perspective is posting would fail with
a timeout reported by the client.
- Article flow from the upstream feeder was at it's lowest point during this period.
- The problem resolved as expireover was nearing completion based on these timestamps:
The last connection issue reported from the upstream feeder:
Jun 24 06:25:44 feed1 innfeed[91878]: <spool1.usenet.blueworldhosting.com>:1 cxnsleep non-responsive connection
Expire output:
Expire messages:
expireover start Thu Jun 23 15:39:00 CDT 2022: ( -z/var/log/news/expire.rm -Z/var/log/news/expire.lowmark)
Article lines processed 53326142
Articles dropped 56726
Overview index dropped 57054
expireover end Fri Jun 24 07:06:07 CDT 2022
lowmarkrenumber begin Fri Jun 24 07:06:07 CDT 2022: (/var/log/news/expire.lowmark)
lowmarkrenumber end Fri Jun 24 07:06:07 CDT 2022
expirerm start Fri Jun 24 07:06:07 CDT 2022
expirerm end Fri Jun 24 07:09:14 CDT 2022
expire begin Fri Jun 24 07:09:44 CDT 2022: (-v1)
Article lines processed 32835813
Articles retained 32805948
Entries expired 29865
expire end Fri Jun 24 08:52:30 CDT 2022
all done Fri Jun 24 08:52:30 CDT 2022
As a follow-up, would you recommend a different overview storage mechanism?
My understanding is that buffindexed would probably make my situation worse
ovdb is a non-starter for me, and ovsqlite has *serious* performance issues. I started building this box with the intent to use ovsqlite, but when I started injecting articles the throughput rate was abysmal.
On Jun 24, 2022 at 12:56:11 PM CDT, "Russ Allbery" in <87a6a2gd38.fsf@hope.eyrie.org> wrote:
Jesse Rehmer <jesse.rehmer@blueworldhosting.com> writes:
My apologies, I did leave out some critical details - I am using
tradspool/tradindexed.
Do you by chance have a really large group that would take a long time to
expire? It's been a while since I wrote the locking strategy for
tradindexed, but expiring a group locks it for write and receiving an
article in the same group will also attempt to lock it for write, and innd >> is single-threaded. So if you receive an article for a group while that
group is being expired, innd will wait for the lock until the expiration
of that group finishes. If that group is extremely large, this could well >> take ten minutes.
I injected articles from 2003-present for almost all of the Big8 groups, so many groups have hundreds of thousands of articles.
I will admit, it has been 10+ years since I've used INN with a spool containing this many articles, but long ago helped another admin move to a new
server. That box was receiving a full feed, I don't recall the number of articles in the spool, but it was several terabytes (my size is ~150GB for comparison). When we ran expireover on that spool the average run time was 6-8
hours and do not recall experiencing any issues like I am seeing. My expireover run on a fraction of the amount of data and on faster hardware was ~14 hours. Is that expected?
"Russ Allbery" in <87a6a2gd38.fsf@hope.eyrie.org> wrote:
Do you by chance have a really large group that would take a long time
to expire? It's been a while since I wrote the locking strategy for
tradindexed, but expiring a group locks it for write and receiving an
article in the same group will also attempt to lock it for write, and
innd is single-threaded. So if you receive an article for a group
while that group is being expired, innd will wait for the lock until
the expiration of that group finishes. If that group is extremely
large, this could well take ten minutes.
I injected articles from 2003-present for almost all of the Big8 groups,
so many groups have hundreds of thousands of articles.
I will admit, it has been 10+ years since I've used INN with a spool containing this many articles, but long ago helped another admin move to
a new server. That box was receiving a full feed, I don't recall the
number of articles in the spool, but it was several terabytes (my size
is ~150GB for comparison). When we ran expireover on that spool the
average run time was 6-8 hours and do not recall experiencing any issues
like I am seeing. My expireover run on a fraction of the amount of data
and on faster hardware was ~14 hours. Is that expected?
Do you by chance have a really large group that would take a long time to expire? It's been a while since I wrote the locking strategy for tradindexed, but expiring a group locks it for write and receiving an
article in the same group will also attempt to lock it for write, and innd
is single-threaded. So if you receive an article for a group while that group is being expired, innd will wait for the lock until the expiration
of that group finishes. If that group is extremely large, this could well take ten minutes.
Hi Jesse,
As a follow-up, would you recommend a different overview storage mechanism?
Incidentally, I was planning to make a video about exactly that subject: explaining how to set up each of the overview storage mechanisms, and comparing them.
I would recommend either tradindexed or ovsqlite.
Nonetheless, I do not have a spool as huge as yours. It seems that performances are not satisfactory with 53 millions of overview lines :-/
ovdb is a non-starter for me, and ovsqlite has *serious* performance issues. >> I started building this box with the intent to use ovsqlite, but when I
started injecting articles the throughput rate was abysmal.
Did you try to increase transrowlimit when injecting your articles?
*:A:1:never:never
*.jobs*:A:1:90:90
*.test:A:1:300:300
news.lists.filters:A:1:10:10
Hi Jesse,
*:A:1:never:never
*.jobs*:A:1:90:90
*.test:A:1:300:300
news.lists.filters:A:1:10:10
You may also want to expire control.cancel sooner... It may get very large...
To sort your newsgroups by increasing article counts, run:
% getlist -R counts | sort -n -k 4
The fourth field contains the number of articles.
I've not looked at the complexity but couldn't the expiration of the
overview of a newsgroup be done in bulks of 100,000 articles for
instance? Lock the group, process the first 100,000 overview lines (and retain that n lines have been dropped), release the lock, try to acquire
a new lock and process the 100,000 next lines from line (100,000 - n),
etc.
Deferring the article back to the peer probably won't work since not all peers honor deferrals and I think the article is already stored before we
try to write overview.
Thanks for the reminder about adding control.cancel... Right now it shouldn't be an issue:
[news@spool1 ~]$ getlist -R counts | sort -n -k 4 | grep control.cancel control.cancel 15447 1 15447 n
However, I can see where ignoring could cause problems in the future. Do you also recommend "control"?
Somehow I've missed the getlist utility all these years... pretty spiffy.
Looks like I have a few groups that are indeed larger than even I expected. I haven't paid attention to the high/low counts and whatnot since beginning the injection project.
rec.arts.tv 1367076 1 1366870 y
If I change:
*:A:1:never:never
to:
*:A:never:never:never
Would that stop expireover from traversing through all the groups and overview
data, except specific groups listed later in expire.ctl?
ovdb is a non-starter for me, and ovsqlite has *serious* performance issues. >> I started building this box with the intent to use ovsqlite, but when I
started injecting articles the throughput rate was abysmal.
Did you try to increase transrowlimit when injecting your articles?
I am going to give ovsqlite another try. I was reading through the
man page and configuration file, paying attention to this recommendation:
A transaction occurs every transrowlimit articles or transtimelimit
seconds, whichever is smaller. You are encouraged to keep the default
value for row limits and, instead, adjust the time limit according to
how many articles your news server usually accepts per second during
normal operation (you can find statistics about incoming articles in
your daily Usenet reports).
Inserting or deleting a database row within a transaction is very fast whereas committing a transaction is slow, especially on rotating
storage. Setting transaction limits too low leads to poor
performance. When rebuilding overview data, it may be worth
temporarily raising these values, though.
Do you recommend increasing both transrowlimit and transtimelimit? I am also looking at the pagesize and cachesize parameters.
| Sysop: | Keyop |
|---|---|
| Location: | Huddersfield, West Yorkshire, UK |
| Users: | 300 |
| Nodes: | 16 (2 / 14) |
| Uptime: | 71:32:43 |
| Calls: | 6,712 |
| Files: | 12,244 |
| Messages: | 5,356,970 |