Censornet Traffic Painfully Slow

[OutToLunch]

Morning all,

 

My Censornet box seems to be having a nervous breakdown today/yesterday. Browsing through it is painfully slow - anyone have any tips on troubleshooting? I'm quite happy poking about in the console to try and work out what's going on but I'm at a loss.

 

It's not the greatest box in the world (1ghz Athlon/512mb) but we only have 20 PCs and a 512k line so it's served us fine for the past year.

 

ps aux shows nothing hogging the CPU and the load averages are pretty normal.

 

top output is -

 

top - 09:47:05 up 23:57, 1 user, load average: 0.05, 0.22, 0.28

Mem: 513688k total, 503060k used, 10628k free, 4184k buffers

Swap: 128512k total, 80k used, 128432k free, 443392k cached

 

Looks a little odd to me but I don't have another CN box to compare to.

 

Plugging a laptop into the router shows that the ADSL connection is behaving normally - ie normal speed browsing when not going through CN.

 

Any ideas before I get lynched? "The internet is slow today, sorry" is only going to keep me alive for so long!

[Geoff]

You ran out of ram. Either tweak the various tunable parameters in Squid so it uses less ram or stick more ram in the machine.

[OutToLunch]

Hmm. Thanks for the quick reply. I did think that looked a bit odd. Any particular reason that it would run fine for over a year on the memory/configuration it has then suddenly decide to throw its dummy out of the pram?

 

I should be able to find another stick somewhere but if it's just going to max it out again due to some other quirk I'd like to know what to look for...

[Geoff]

Someone's thrashing your internet connection? Do you have any bandwidth statistics to compare and contrast usage?

[OutToLunch]

At 512kb DSL shared between 2 ICT suites + random users our internet connection is always thrashing Didn't seem to be anyone doing anything interesting but I'll double check. Thanks.

[Geoff]

Anything involving big files. Video is an obvious one for example.

[OutToLunch]

Youtube/Googlevideo and the like all blocked here, *.WMV/MPG/AVI filtered and unblocked on an as needed basis - can't afford to waste the bandwidth usually.

 

It's not as painful as it was when we were sharing the whole lot over ISDN, but has off days - what's confusing me at the moment is that nothing seems to have changed traffic wise, and the nets fine without CN - just the traffic through it slowed to a crawl. Currently downloading a 1mb zip file at 3k/sec with no other users about.

 

Looks like I need to google up some docs on troubleshooting Squid...

[OutToLunch]

Hmm. Sorry to bang on about it, but 1 hour after a good old fashioned reboot

 

top - 11:10:30 up 1:00, 1 user, load average: 0.80, 0.25, 0.23

Tasks: 91 total, 2 running, 89 sleeping, 0 stopped, 0 zombie

Cpu(s): 14.7% us, 15.0% sy, 0.0% ni, 0.0% id, 69.0% wa, 1.3% hi, 0.0% si

Mem: 513688k total, 508904k used, 4784k free, 3108k buffers

Swap: 128512k total, 4k used, 128508k free, 450452k cached

 

Managed to SSH in to an even lower specced CN box on one of my remote sites and :

 

10:52:05 up 13 days, 2:49, 1 user, load average: 2.54, 3.45, 3.10

86 processes: 83 sleeping, 3 running, 0 zombie, 0 stopped

CPU states: 39.5% user, 25.4% system, 0.0% nice, 35.1% idle

Mem: 320280K total, 313092K used, 7188K free, 4812K buffers

Swap: 128516K total, 53180K used, 75336K free, 229452K cached

 

No complaints or speed problems from the other site despite it being obviously hammered - one thing I do notice is that the CN box on the other site is using swap while the local CN box seems blissfully ignorant of it (4k used?!). Just to confuse things, the misbehaving box is showing "Free RAM

89%" on the web based admin status page. Argh!

 

Any tips on what to prod to find out if there are reasons for this?

[Geoff]

1. Run top.

2. Press shift-O.

2. Press Q

3. Press Esc

 

Whatever is at the top of the list is what's eating your ram.

[OutToLunch]

Having a bit of a brain freeze - the older box is running CN 3.2 and a different version of top so output isn't quite the same, but something definitely seems amiss in the results from the newer / CN 3.3 box.

 

12:59:26 up 13 days, 4:57, 1 user, load average: 2.85, 2.13, 2.11

83 processes: 78 sleeping, 5 running, 0 zombie, 0 stopped

CPU states: 47.7% user, 26.7% system, 0.0% nice, 25.6% idle

Mem: 320280K total, 314844K used, 5436K free, 1872K buffers

Swap: 128516K total, 53368K used, 75148K free, 231720K cached

 

SIZE PID USER PRI NI RSS SHARE STAT %CPU %MEM TIME COMMAND

10884 29094 postgres 12 0 10M 10152 D 5.9 3.3 0:50 postmaster

40800 280 nobody 11 0 34M 20368 R 1.8 11.1 85:08 squid

972 29642 admin 14 0 972 748 R 1.1 0.3 0:01 top

3268 30400 postgres 16 0 3112 2588 S 0.9 0.9 0:00 postmaster

3280 30397 postgres 14 0 3124 2596 S 0.7 0.9 0:00 postmaster

0 4 root 9 0 0 0 SW 0.5 0.0 27:03 kswapd

8420 12344 nobody 9 0 4088 4032 S 0.5 1.2 0:11 dansguardian

856 361 postgres 0 0 592 540 S 0.3 0.1 9:27 postmaster

2384 373 postgres 9 0 2156 2124 S 0.3 0.6 1:36 postmaster

10856 12345 nobody 9 0 6428 3892 S 0.3 2.0 0:11 dansguardian

8592 30399 nobody 12 0 1584 1420 S 0.3 0.4 0:00 dansguardian

1448 374 postgres 9 0 1232 992 S 0.1 0.3 4:35 postmaster

8304 12343 nobody 0 0 976 956 S 0.1 0.3 0:47 dansguardian

1636 29567 root 9 0 1612 1320 R 0.1 0.5 0:00 sshd

8592 30396 nobody 11 0 1608 1444 R 0.1 0.5 0:00 dansguardian

408 1 root 8 0 364 344 S 0.0 0.1 0:25 init

0 2 root 9 0 0 0 SW 0.0 0.0 0:00 keventd

0 3 root 19 19 0 0 SWN 0.0 0.0 0:00 ksoftirqd_CPU0

0 5 root 9 0 0 0 SW 0.0 0.0 0:00 bdflush

0 6 root 9 0 0 0 SW 0.0 0.0 0:14 kupdated

0 8 root 9 0 0 0 RW 0.0 0.0 1:54 kjournald

516 189 root 9 0 500 436 S 0.0 0.1 0:46 syslogd

1272 192 root 9 0 328 328 S 0.0 0.1 0:00 klogd

...

 

On the misbehaving box -

 

top - 13:25:28 up 3:15, 1 user, load average: 1.02, 0.58, 0.57

Tasks: 114 total, 2 running, 112 sleeping, 0 stopped, 0 zombie

Cpu(s): 50.5% us, 8.2% sy, 0.0% ni, 0.0% id, 40.7% wa, 0.5% hi, 0.0% si

Mem: 513688k total, 510624k used, 3064k free, 4268k buffers

Swap: 128512k total, 4k used, 128508k free, 441608k cached

 

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

21159 nobody 15 0 18136 15m 2252 S 0.0 3.1 0:42.13 squid

28480 postgres 20 0 23292 10m 21m R 57.3 2.2 0:15.65 postmaster

21295 nobody 15 0 13328 9384 3808 S 0.0 1.8 0:01.95 dansguardian

28021 nobody 16 0 11120 8856 3808 S 0.0 1.7 0:00.03 dansguardian

28019 nobody 16 0 11080 8804 3808 S 0.0 1.7 0:00.02 dansguardian

28441 nobody 16 0 11020 8676 3808 S 0.0 1.7 0:00.00 dansguardian

28427 nobody 16 0 10924 8620 3808 S 0.0 1.7 0:00.01 dansguardian

28904 nobody 16 0 10904 8616 3808 S 0.0 1.7 0:00.00 dansguardian

25845 nobody 16 0 10924 8612 3808 S 0.0 1.7 0:00.03 dansguardian

27922 nobody 16 0 10924 8612 3808 S 0.0 1.7 0:00.01 dansguardian

28324 nobody 16 0 10924 8612 3808 S 0.0 1.7 0:00.01 dansguardian

28396 nobody 16 0 10924 8612 3808 S 0.0 1.7 0:00.00 dansguardian

28896 nobody 16 0 10924 8612 3808 S 0.0 1.7 0:00.00 dansguardian

23240 nobody 16 0 10928 8580 3808 S 0.0 1.7 0:00.56 dansguardian

23385 nobody 16 0 10928 8576 3808 S 0.0 1.7 0:00.47 dansguardian

21294 nobody 16 0 10888 8448 3808 S 0.0 1.6 0:00.14 dansguardian

21293 nobody 15 0 10884 8440 3808 S 0.0 1.6 0:37.70 dansguardian

28897 postgres 16 0 23564 4648 21m S 0.0 0.9 0:00.02 postmaster

25846 postgres 18 0 23172 3668 21m S 0.0 0.7 0:00.01 postmaster

27923 postgres 17 0 23172 3660 21m S 0.0 0.7 0:00.01 postmaster

28325 postgres 17 0 23172 3656 21m S 0.0 0.7 0:00.01 postmaster

28020 postgres 17 0 23172 3652 21m S 0.0 0.7 0:00.01 postmaster

28022 postgres 18 0 23172 3652 21m S 0.0 0.7 0:00.01 postmaster

28397 postgres 17 0 23172 3652 21m S 0.0 0.7 0:00.00 postmaster

28428 postgres 17 0 23172 3652 21m S 0.0 0.7 0:00.01 postmaster

28442 postgres 18 0 23172 3652 21m S 0.0 0.7 0:00.01 postmaster

28905 postgres 17 0 23172 3652 21m S 0.0 0.7 0:00.01 postmaster

23241 postgres 17 0 23172 3424 21m S 0.0 0.7 0:00.01 postmaster

23390 postgres 17 0 23172 3424 21m S 0.0 0.7 0:00.01 postmaster

28467 root 16 0 5488 3336 3540 S 0.0 0.6 0:00.09 process_web_log

20095 postgres 15 0 23716 2600 21m S 0.0 0.5 0:01.95 postmaster

897 root 16 0 2232 2224 1992 S 0.0 0.4 0:00.06 ntpd

1265 root 16 0 3724 2148 2932 S 0.0 0.4 0:03.79 sshd

674 root 15 0 3248 2060 2440 S 0.0 0.4 0:00.18 snmpd

20096 postgres 15 0 22988 2044 21m S 0.0 0.4 0:01.40 postmaster

20093 postgres 16 0 22724 1880 21m S 0.0 0.4 0:16.59 postmaster

362 root 16 0 2656 1720 1344 S 0.0 0.3 0:00.19 klogd

20557 www-data 16 0 3280 1652 2776 S 0.0 0.3 0:00.08 apache

20560 www-data 16 0 3276 1652 2776 S 0.0 0.3 0:00.03 apache

20559 www-data 16 0 3276 1640 2776 S 0.0 0.3 0:00.01 apache

 

Again, it seems determined not to use any swap, but maybe that's normal for CN 3.3? The dansguardian and postmaster processes seem to be running amok but that's where my 'expertise' ends.

 

I don't have another CN box of the same version to compare to

[Geoff]

Well there doesn't seem to be any tragic memory misuage there. I am concerned about PID 28480 gobbling half your CPU time though. What's 'postmaster' it's not a standard *nix command AFAIK. Something mail related perhaps? But then why is it running as 'postgres' (presumably the database user account?).

 

Do you have sysstat installed? (iostat, sar, mpstat, and friends)?

[Stese]

I've seen Postgres as part of a Web Server, and it's installed by QCA KS3 testing... if that helps any

[Geoff]

I know what it is, Postgres is a Database server. However in the context above, that makes no sense. As I've explained.

[OutToLunch]

I don't know myself what postmaster is or what it's doing but apparently...

 

postmaster is the PostgreSQL multiuser database server. In order for a client application to access a database it connects (over a network or locally) to a running postmaster. The postmaster then starts a separate server process ("postgres") to handle the connection. The postmaster also manages the communication among server processes.

 

http://www.postgresql.org/docs/8.1/static/app-postmaster.html

 

I think CN uses postgresql for its internal databases. Unfortunately with the CN forum long gone it's pretty tricky to find out any of the old information which may have been covered many times over there. It's looking like something's got out of control on the backend but I haven't made any changes to the system recently...

 

Nothing showing up on whereis for any of the sysstat tools, just waiting for a find / to complete but I doubt CN has any useful extra tools packaged with it

[Geoff]

ok, restart postgres then. That'll fix it.

[OutToLunch]

Rebooted several times already - just starts racking up the processes again as soon as it's finished reloading

[Geoff]

There's obviously something going on between the database server and whatever is talking to it.

 

What sort of data is in the database?

[OutToLunch]

It's the internal database of blacklisted names/URLs etc. I think I've nailed it though, fingers crossed - I'd added a user to the limited bandwidth list, rather than suspending their internet access. Censornet seems to generate a broken squid template for this, which somehow causes all sorts of horrendous errors and processes spewing all over the place.

 

*fingers crossed i'm not speaking too soon*

 

I'd still love to know why it never touches the swap file, but that doesn't seem to be related to the issue at hand. I'm only familiar with the windows concept of swap files so maybe I'm misunderstanding about when/where it should be being used.

[tom_newton]

I'm not sure wether the db stores log info as well as configs - i *think* it does (its a while since I disassembled a CN). It may be that you've simply got too full a log db.

[Geoff]

I refer you to the Linux Swap Space mini-HOWTO.

 

http://www.xenotime.net/linux/doc/swap-mini-howto.txt

[OutToLunch]

Think I've cracked it now. It wasn't finding the ACL file for users who should be on 2kb/sec, so it seems it was applying it to everyone - hence the painful slowness. I guess the additional processes are a hangover of waiting for all the requests to complete to log them...

 

I refer you to the Linux Swap Space mini-HOWTO.

 

http://www.xenotime.net/linux/doc/swap-mini-howto.txt

 

Thank you for that and your patience with the rest of my questions.

[Geoff]

That would make sense.

[ChrisH]

Think I've cracked it now. It wasn't finding the ACL file for users who should be on 2kb/sec, so it seems it was applying it to everyone - hence the painful slowness. I guess the additional processes are a hangover of waiting for all the requests to complete to log them...

 

I have seen that before on Censornet installs... I should get round to trying the new version that comes as a debian package this wee.