[squid-users] FATAL: Received Segment Violation...dying.

From: Raymond A. Meijer <rmeijer@dont-contact.us>
Date: Fri, 23 Apr 2004 14:02:30 +0300

Hello,

I have a Dual PIII/866MHz Fedora Core 1 box with 1x9GB and 1x18GB SCSI disks
for squid and 2.5GB memory.

Only 50% of the disks is being used for the spool (formatted in ReiserFS
3.6). The other 50% of the disks is formatted in Ext3 (for performance
testing), but not mounted at the moment.

I've downloaded the sources for SQUID2.5.STABLE5 and compiled them with
gcc-3.3.2-6 and glibc-2.3.2-101.4 and the following configure options:

--prefix=/opt/squid-2.5.STABLE5 --enable-linux-netfilter --enable-async-io=24
--enable-dlmalloc --enable-underscores '--enable-removal-policies=lru heap'

CFLAGS was "-O6 -s -DNUMTHREADS=24" at compile time.

The ip_wccp version being used is:

ip_wccp.c,v 1.5 2004/02/17 01:55:05

Squid worked fine for about 1.5 hours, but suddenly it died with a Segment
Violation.

See the cache.log:

2004/04/23 11:51:29| Starting Squid Cache version 2.5.STABLE5 for i686-pc-linux-gnu...
2004/04/23 11:51:29| Process ID 4115
2004/04/23 11:51:29| With 4096 file descriptors available
2004/04/23 11:51:29| Performing DNS Tests...
2004/04/23 11:51:29| Successful DNS name lookup tests...
2004/04/23 11:51:29| DNS Socket created at 0.0.0.0, port 32776, FD 4
2004/04/23 11:51:29| Adding nameserver 62.1.1.92 from /etc/resolv.conf
2004/04/23 11:51:29| Adding nameserver 62.1.1.62 from /etc/resolv.conf
2004/04/23 11:51:29| Unlinkd pipe opened on FD 9
2004/04/23 11:51:29| Swap maxSize 20480000 KB, estimated 1575384 objects
2004/04/23 11:51:29| Target number of buckets: 78769
2004/04/23 11:51:29| Using 131072 Store buckets
2004/04/23 11:51:29| Max Mem size: 8192 KB
2004/04/23 11:51:29| Max Swap size: 20480000 KB
2004/04/23 11:51:29| Rebuilding storage in /opt/squid/var/cache/disk1 (CLEAN)
2004/04/23 11:51:29| Rebuilding storage in /opt/squid/var/cache/disk2 (CLEAN)
2004/04/23 11:51:29| Using Least Load store dir selection
2004/04/23 11:51:29| Set Current Directory to /opt/squid/var/cache
2004/04/23 11:51:29| Loaded Icons.
2004/04/23 11:51:29| Accepting HTTP connections at 0.0.0.0, port 3128, FD 12.
2004/04/23 11:51:29| Accepting WCCP messages on port 2048, FD 13.
2004/04/23 11:51:29| Ready to serve requests.
2004/04/23 11:51:30| Store rebuilding is 19.9% complete
2004/04/23 11:51:30| Done scanning /opt/squid/var/cache/disk2 swaplog (0 entries)
2004/04/23 11:51:30| Done reading /opt/squid/var/cache/disk1 swaplog (20571 entries)
2004/04/23 11:51:30| Finished rebuilding storage from disk.
2004/04/23 11:51:30| 20571 Entries scanned
2004/04/23 11:51:30| 0 Invalid entries.
2004/04/23 11:51:30| 0 With invalid flags.
2004/04/23 11:51:30| 20571 Objects loaded.
2004/04/23 11:51:30| 0 Objects expired.
2004/04/23 11:51:30| 0 Objects cancelled.
2004/04/23 11:51:30| 0 Duplicate URLs purged.
2004/04/23 11:51:30| 0 Swapfile clashes avoided.
2004/04/23 11:51:30| Took 1.0 seconds (20430.0 objects/sec).
2004/04/23 11:51:30| Beginning Validation Procedure
2004/04/23 11:51:30| Completed Validation Procedure
2004/04/23 11:51:30| Validated 20571 Entries
2004/04/23 11:51:30| store_swap_size = 279824k
2004/04/23 11:51:31| storeLateRelease: released 0 objects
2004/04/23 12:02:30| squidaio_queue_request: WARNING - Queue congestion
2004/04/23 12:54:13| squidaio_queue_request: WARNING - Queue congestion
2004/04/23 13:23:16| squidaio_queue_request: WARNING - Queue congestion
2004/04/23 13:27:55| CACHEMGR: root@127.0.0.1 requesting 'info'
FATAL: Received Segment Violation...dying.
2004/04/23 13:29:55| storeDirWriteCleanLogs: Starting...
2004/04/23 13:29:55| WARNING: Closing open FD 12
2004/04/23 13:29:56| 65536 entries written so far.
2004/04/23 13:29:56| Finished. Wrote 69628 entries.
2004/04/23 13:29:56| Took 0.1 seconds (649696.7 entries/sec).
CPU Usage: 4228.510 seconds = 1153.910 user + 3074.600 sys
Maximum Resident Size: 0 KB
Page faults with physical i/o: 418
Memory usage for squid via mallinfo():
        total space in arena: 27308 KB
        Ordinary blocks: 23302 KB 7935 blks
        Small blocks: 0 KB 0 blks
        Holding blocks: 1592 KB 3 blks
        Free Small blocks: 0 KB
        Free Ordinary blocks: 4005 KB
        Total in use: 24894 KB 91%
        Total free: 4005 KB 15%
2004/04/23 13:29:59| Starting Squid Cache version 2.5.STABLE5 for i686-pc-linux-gnu...
2004/04/23 13:29:59| Process ID 6560
2004/04/23 13:29:59| With 4096 file descriptors available
2004/04/23 13:29:59| Performing DNS Tests...
2004/04/23 13:29:59| Successful DNS name lookup tests...
2004/04/23 13:29:59| DNS Socket created at 0.0.0.0, port 32777, FD 4
2004/04/23 13:29:59| Adding nameserver 62.1.1.92 from /etc/resolv.conf
2004/04/23 13:29:59| Adding nameserver 62.1.1.62 from /etc/resolv.conf
2004/04/23 13:29:59| Unlinkd pipe opened on FD 9
2004/04/23 13:29:59| Swap maxSize 20480000 KB, estimated 1575384 objects
2004/04/23 13:29:59| Target number of buckets: 78769
2004/04/23 13:29:59| Using 131072 Store buckets
2004/04/23 13:29:59| Max Mem size: 8192 KB
2004/04/23 13:29:59| Max Swap size: 20480000 KB
2004/04/23 13:29:59| Rebuilding storage in /opt/squid/var/cache/disk1 (CLEAN)
2004/04/23 13:29:59| Rebuilding storage in /opt/squid/var/cache/disk2 (CLEAN)
2004/04/23 13:29:59| Using Least Load store dir selection
2004/04/23 13:29:59| Set Current Directory to /opt/squid/var/cache
2004/04/23 13:29:59| Loaded Icons.
2004/04/23 13:29:59| Accepting HTTP connections at 0.0.0.0, port 3128, FD 12.
2004/04/23 13:29:59| Accepting WCCP messages on port 2048, FD 13.
2004/04/23 13:29:59| Ready to serve requests.
2004/04/23 13:29:59| Store rebuilding is 5.9% complete
2004/04/23 13:29:59| Done scanning /opt/squid/var/cache/disk2 swaplog (0 entries)
2004/04/23 13:30:01| Done reading /opt/squid/var/cache/disk1 swaplog (69628 entries)
2004/04/23 13:30:01| Finished rebuilding storage from disk.
2004/04/23 13:30:01| 69628 Entries scanned
2004/04/23 13:30:01| 0 Invalid entries.
2004/04/23 13:30:01| 0 With invalid flags.
2004/04/23 13:30:01| 69609 Objects loaded.
2004/04/23 13:30:01| 0 Objects expired.
2004/04/23 13:30:01| 0 Objects cancelled.
2004/04/23 13:30:01| 3 Duplicate URLs purged.
2004/04/23 13:30:01| 16 Swapfile clashes avoided.
2004/04/23 13:30:01| Took 2.2 seconds (31729.9 objects/sec).
2004/04/23 13:30:01| Beginning Validation Procedure
2004/04/23 13:30:01| Completed Validation Procedure
2004/04/23 13:30:01| Validated 69609 Entries
2004/04/23 13:30:01| store_swap_size = 1003412k
2004/04/23 13:30:02| storeLateRelease: released 0 objects

I had 'vmstat 5' running in another window at that time, but I don't think it
show anything useful:

procs memory swap io system cpu
 r b swpd free buff cache si so bi bo in cs us sy wa id
 1 0 0 1509492 87876 838552 0 0 3 278 941 239 9 25 0 66
 1 0 0 1508732 87904 839212 0 0 0 260 981 230 9 27 0 64
 0 0 0 1508220 87924 839672 0 0 0 218 874 189 7 23 0 70
 1 0 0 1507496 87952 840296 0 0 0 234 948 204 7 27 0 65
 0 0 0 1506336 87984 841360 0 0 0 274 1002 231 9 26 0 65
 1 0 0 1505472 88000 842148 0 0 0 218 1008 231 9 26 0 65
 0 0 0 1504576 88024 842976 0 0 4 225 930 220 9 22 0 69
 0 0 0 1504012 88044 843464 0 0 0 210 870 216 7 24 0 68
 0 0 0 1503392 88088 843996 0 0 14 166 988 243 9 25 0 66
 0 0 0 1502412 88116 844896 0 0 17 186 1056 233 10 27 0 64
 1 0 0 1501592 88148 845644 0 0 10 254 1048 239 10 26 0 64
 1 0 0 1500792 88180 846440 0 0 14 217 942 270 9 26 0 65
 1 0 0 1499428 88212 847660 0 0 10 243 1005 246 10 26 0 64
 0 0 0 1498080 88264 848840 0 0 13 195 1019 300 10 29 0 61
 0 0 0 1496892 88300 849936 0 0 6 200 1002 253 10 26 0 63
 0 0 0 1496556 88316 850196 0 0 3 235 1020 223 8 28 0 64
 1 0 0 1495692 88340 850980 0 0 2 199 1067 229 9 28 0 63
 0 0 0 1495596 88380 851012 0 0 1 209 956 217 9 24 0 67
 0 0 0 1494908 88404 851636 0 0 1 294 967 206 9 26 0 65
 1 0 0 1494000 88428 852476 0 0 5 302 905 267 10 26 0 64
 0 0 0 1493084 88432 853320 0 0 14 254 928 277 10 25 0 65
 0 0 0 1491772 88476 854140 0 0 8 260 1071 300 10 28 0 61
 0 0 0 1490660 88504 855148 0 0 0 213 974 246 9 25 0 66
 0 0 0 1490088 88532 855736 0 0 0 238 858 263 7 24 0 68
 1 0 0 1489436 88552 856328 0 0 0 192 911 313 7 23 0 69
 1 0 0 1489000 88576 856668 0 0 0 232 1041 273 11 26 0 64
 0 0 0 1488260 88596 857232 0 0 0 223 1005 261 8 25 0 66
 0 0 0 1487548 88620 857884 0 0 2 223 1036 278 11 24 0 65
 0 0 0 1486440 88644 858856 0 0 2 303 1110 256 11 28 0 61
 1 0 0 1485684 88680 859508 0 0 6 158 1063 275 11 27 0 62
 0 0 0 1484544 88704 860544 0 0 1 205 1014 225 9 26 0 65
 0 0 0 1483560 88732 861452 0 0 0 234 1026 237 11 24 0 65
 1 0 0 1482384 88764 862532 0 0 0 185 1124 307 11 27 0 62
 0 0 0 1481424 88780 863380 0 0 4 197 991 244 9 26 0 65
 0 0 0 1510300 88844 863376 0 0 0 282 1296 137 4 11 0 85
 0 1 0 1496908 88892 863600 0 0 1 186 880 373 10 18 0 72
 1 0 0 1495828 88896 863432 0 0 1 205 742 329 3 6 0 90
 0 0 0 1501500 88920 857184 0 0 2 328 1070 525 5 11 0 84
 0 0 0 1504680 88948 852712 0 0 7 475 1027 422 5 14 0 81
 0 0 0 1506428 88980 849460 0 0 15 282 1097 426 8 16 0 77
 0 0 0 1504836 89004 850264 0 0 0 213 1034 400 7 19 0 75
 0 0 0 1502432 89032 851100 0 0 0 306 1031 395 7 20 0 73
 0 0 0 1499912 89068 852244 0 0 0 629 1061 355 9 22 0 69
 0 0 0 1497924 89100 853192 0 0 1 123 1020 352 6 21 0 73
 0 0 0 1495816 89120 853880 0 0 0 190 962 362 9 21 0 70
 0 0 0 1493728 89148 854712 0 0 0 180 1077 366 11 24 0 65
 0 0 0 1491808 89184 855488 0 0 0 289 1053 270 11 25 0 65
 0 0 0 1490576 89212 856236 0 0 0 195 1022 279 8 25 0 67
 0 0 0 1490032 89232 856732 0 0 0 273 871 227 7 22 0 71
 0 0 0 1488908 89264 857616 0 0 1 294 986 305 9 25 0 66
procs memory swap io system cpu
 r b swpd free buff cache si so bi bo in cs us sy wa id
 0 0 0 1487928 89280 858320 0 0 1 195 1020 271 9 28 0 64
 0 0 0 1486648 89308 859244 0 0 0 248 897 297 8 24 0 69
 0 0 0 1485564 89340 860068 0 0 0 225 933 288 7 28 0 65
 0 0 0 1484244 89372 861016 0 0 1 188 1054 291 10 29 0 61
 1 0 0 1483132 89400 862056 0 0 18 204 1059 259 10 26 0 64
 1 0 0 1481692 89440 863296 0 0 9 273 1107 253 9 31 0 60
 2 0 0 1480904 89460 864020 0 0 0 266 1001 256 10 26 0 63
 0 0 0 1479940 89492 864808 0 0 1 268 1062 226 10 28 0 62
 0 0 0 1479236 89512 865372 0 0 0 194 923 210 7 27 0 66
 0 0 0 1478608 89524 866000 0 0 0 239 792 226 7 21 0 72
 0 0 0 1477800 89536 866720 0 0 10 240 868 216 8 23 0 69
 0 0 0 1477024 89568 867396 0 0 3 321 865 246 8 25 0 67
 0 0 0 1476596 89588 867756 0 0 1 210 851 233 8 24 0 68
 0 0 0 1475600 89612 868632 0 0 0 270 985 208 7 27 0 66
 0 0 0 1474876 89636 869312 0 0 2 159 941 222 8 26 0 66
 0 0 0 1473812 89656 870204 0 0 0 156 953 263 8 25 0 67
 1 0 0 1472468 89684 871420 0 0 0 165 1034 254 9 26 0 65
 1 0 0 1470600 89728 872908 0 0 34 228 1133 285 9 29 0 62
 1 0 0 1469384 89752 873984 0 0 14 153 981 314 9 26 0 65
 1 0 0 1468324 89788 874972 0 0 0 301 868 320 10 24 0 67
 1 0 0 1467296 89816 875888 0 0 0 204 887 323 9 24 0 67
 1 0 0 1466244 89840 876816 0 0 0 208 842 233 7 24 0 69
 0 0 0 1465264 89872 877648 0 0 0 227 859 238 7 22 0 71
 0 0 0 1464440 89892 878408 0 0 1 336 823 235 7 22 0 71
 0 0 0 1463920 89920 878860 0 0 7 332 747 241 7 20 0 73
 0 0 0 1463232 89948 879456 0 0 0 227 801 213 5 20 0 74
 1 0 0 1462560 89976 880068 0 0 0 294 866 275 8 24 0 69
 0 0 0 1461656 90000 880860 0 0 0 195 878 240 6 24 0 70
 0 0 0 1460932 90020 881504 0 0 0 259 879 260 9 25 0 66
 0 0 0 1459776 90044 882444 0 0 1 198 912 258 9 26 0 65
 1 0 0 1458832 90060 883176 0 0 1 197 1006 270 10 28 0 63
 0 0 0 1458212 90088 883732 0 0 0 214 897 247 9 26 0 65
 1 0 0 1457420 90120 884408 0 0 5 162 918 260 8 29 0 63
 1 0 0 1456524 90152 885132 0 0 0 218 840 296 10 25 0 65
 0 0 0 1455760 90176 885716 0 0 0 186 952 230 9 25 0 66
 0 0 0 1454504 90204 886512 0 0 6 244 1049 312 10 30 0 60
 0 0 0 1453472 90224 887208 0 0 2 218 1057 212 8 34 0 57
 0 0 0 1452908 90232 887748 0 0 0 184 944 198 9 30 0 62
 1 0 0 1452420 90256 888168 0 0 0 158 861 259 11 25 0 64
 1 0 0 1451672 90284 888808 0 0 0 220 795 269 9 25 0 67
 0 0 0 1450860 90312 889524 0 0 0 202 942 241 8 30 0 62
 0 0 0 1450360 90328 890000 0 0 1 173 889 254 9 29 0 62
 1 0 0 1449432 90348 890760 0 0 0 252 1108 268 10 29 0 61
 0 0 0 1448224 90384 891768 0 0 2 151 1198 258 12 32 0 56
 1 0 0 1447488 90416 892396 0 0 0 193 971 235 9 29 0 62
 0 0 0 1446152 90432 893112 0 0 0 218 935 321 12 33 0 55
 0 0 0 1445180 90468 893960 0 0 0 188 971 244 9 29 0 62
 1 0 0 1445108 90492 894424 0 0 1 183 833 210 7 26 0 67
 0 0 0 1444320 90520 895220 0 0 0 262 965 289 9 28 0 63
 0 0 0 1443212 90552 896188 0 0 0 267 1034 238 10 29 0 61
procs memory swap io system cpu
 r b swpd free buff cache si so bi bo in cs us sy wa id
 1 0 0 1442340 90572 896956 0 0 0 220 953 256 8 28 0 64
 0 1 0 1441316 90592 897896 0 0 0 222 899 280 9 27 0 64
 0 0 0 1440636 90612 898504 0 0 0 247 766 193 7 23 0 70
 0 2 0 1439916 90628 899196 0 0 1 69 904 227 9 26 0 65
 0 3 0 1439092 90636 899948 0 0 0 122 1043 285 10 29 0 60
 0 0 0 1438532 90668 900420 0 0 0 213 943 226 10 26 0 65
 1 0 0 1438016 90684 900880 0 0 0 227 918 240 9 26 0 65
 0 0 0 1437256 90716 901516 0 0 1 242 978 221 9 26 0 66

These are the relevant bits of my squid.conf:
 
http_port 3128
icp_port 0
hierarchy_stoplist cgi-bin ?
acl QUERY urlpath_regex cgi-bin \?
no_cache deny QUERY
cache_mem 8 MB
cache_swap_low 90
cache_swap_high 95
maximum_object_size 16384 KB
maximum_object_size_in_memory 64 KB
ipcache_size 4096
ipcache_low 90
ipcache_high 95
fqdncache_size 4096
cache_replacement_policy heap LFUDA
memory_replacement_policy heap LFUDA
cache_dir aufs /opt/squid/var/cache/disk1 14000 16 256
cache_dir aufs /opt/squid/var/cache/disk2 6000 16 256
cache_store_log /opt/squid/var/logs/store.log
auth_param basic children 5
auth_param basic realm Squid proxy-caching web server
auth_param basic credentialsttl 2 hours
refresh_pattern ^ftp: 1440 20% 10080
refresh_pattern ^gopher: 1440 0% 1440
refresh_pattern . 0 20% 4320
persistent_request_timeout 5 minutes
client_lifetime 12 hours
half_closed_clients off
icp_access deny all
cache_mgr root
cache_effective_user nobody
cache_effective_group nobody
visible_hostname squidcache.internet.gr
httpd_accel_host virtual
httpd_accel_port 80
httpd_accel_with_proxy on
httpd_accel_uses_host_header on
memory_pools off
forwarded_for on
wccp_router aaa.bbb.ccc.ddd
wccp_version 4
coredump_dir /opt/squid/var/cache
pipeline_prefetch off
extension_methods ICSP RSP

Memory usage (note: no swap space):

             total used free shared buffers cached
Mem: 2586572 1161276 1425296 0 91084 912660
-/+ buffers/cache: 157532 2429040
Swap: 0 0 0

The spool partitions:

Filesystem Type 1M-blocks Used Available Use% Mounted on
/dev/sdc2 reiserfs 17366 1028 16339 6% /opt/squid/var/cache/disk1
/dev/sdb2 reiserfs 8683 33 8651 1% /opt/squid/var/cache/disk2

And finally, the output of the cache manager just before squid died:

HTTP/1.0 200 OK
Server: squid/2.5.STABLE5
Mime-Version: 1.0
Date: Fri, 23 Apr 2004 10:27:55 GMT
Content-Type: text/plain
Expires: Fri, 23 Apr 2004 10:27:55 GMT
Last-Modified: Fri, 23 Apr 2004 10:27:55 GMT
X-Cache: MISS from squidcache.internet.gr
Proxy-Connection: close

Squid Object Cache: Version 2.5.STABLE5
Start Time: Fri, 23 Apr 2004 08:51:29 GMT
Current Time: Fri, 23 Apr 2004 10:27:55 GMT
Connection information for squid:
        Number of clients accessing cache: 244
        Number of HTTP requests received: 211181
        Number of ICP messages received: 0
        Number of ICP messages sent: 0
        Number of queued ICP replies: 0
        Request failure ratio: 0.00
        Average HTTP requests per minute since start: 2189.8
        Average ICP messages per minute since start: 0.0
        Select loop called: 1334526 times, 4.336 ms avg
Cache information for squid:
        Request Hit Ratios: 5min: 22.5%, 60min: 22.2%
        Byte Hit Ratios: 5min: 6.4%, 60min: 4.5%
        Request Memory Hit Ratios: 5min: 8.9%, 60min: 3.9%
        Request Disk Hit Ratios: 5min: 31.9%, 60min: 29.6%
        Storage Swap size: 992480 KB
        Storage Mem size: 8172 KB
        Mean Object Size: 14.50 KB
        Requests given to unlinkd: 0
Median Service Times (seconds) 5 min 60 min:
        HTTP Requests (All): 0.30459 0.32154
        Cache Misses: 0.46965 0.46965
        Cache Hits: 0.00678 0.00678
        Near Hits: 0.24524 0.25890
        Not-Modified Replies: 0.00562 0.00562
        DNS Lookups: 0.00860 0.00860
        ICP Queries: 0.00000 0.00000
Resource usage for squid:
        UP Time: 5786.354 seconds
        CPU Time: 4145.880 seconds
        CPU Usage: 71.65%
        CPU Usage, 5 minute avg: 69.84%
        CPU Usage, 60 minute avg: 70.40%
        Process Data Segment Size via sbrk(): 27276 KB
        Maximum Resident Size: 0 KB
        Page faults with physical i/o: 418
Memory usage for squid via mallinfo():
        Total space in arena: 27276 KB
        Ordinary blocks: 23322 KB 6991 blks
        Small blocks: 0 KB 0 blks
        Holding blocks: 1592 KB 3 blks
        Free Small blocks: 0 KB
        Free Ordinary blocks: 3953 KB
        Total in use: 24914 KB 86%
        Total free: 3953 KB 14%
        Total size: 28868 KB
Memory accounted for:
        Total accounted: 17887 KB
        memPoolAlloc calls: 30748011
        memPoolFree calls: 30581059
File descriptor usage for squid:
        Maximum number of file descriptors: 4096
        Largest file desc currently in use: 1164
        Number of file desc currently in use: 1097
        Files queued for open: 0
        Available number of file descriptors: 2999
        Reserved number of file descriptors: 100
        Store Disk files open: 29
Internal Data Structures:
         68589 StoreEntries
           899 StoreEntries with MemObjects
           784 Hot Object Cache Items
         68433 on-disk objects

Can anybody tell from all this why squid crashed and restarted itself? Is
there anything wrong in it's configuration or configure options?

Should I run 'squid -k debug'?

Thank you very much for reading all this ;)

Ray
Received on Fri Apr 23 2004 - 05:02:36 MDT

This archive was generated by hypermail pre-2.1.9 : Fri Apr 30 2004 - 12:00:02 MDT