You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@trafficserver.apache.org by "Van Doorn, Jan R" <Ja...@cable.comcast.com> on 2012/03/20 19:48:43 UTC
Trafficserver startup.
Hi,
When I startup trafficserver, I takes about 3-4 minutes for it to say "NOTE: cache enabled". In that time, the cache is serving requests, but it's not writing to the cache, the CPU usage is very high (E_NET threads), and sometimes clients will hang when they try to get data from/through the cache.
Is this normal? Should I wait with redirecting traffic to the cache until i get this ""NOTE: cache enabled" message? I am using 3.0.2 on a pretty beefy new box with ~11TB of cache over 14 spindles.
Some screenscrapes that may be relevant below.
Rgds,
JvD
/usr/local/bin/traffic_server -T"cache_init" output (note the gap in time where I bolded the lines):
---
[TrafficServer] using root directory '/usr/local'
[Mar 19 16:21:20.953] {139643745757152} STATUS: opened /usr/local/var/log/trafficserver/diags.log
[Mar 19 16:21:20.953] {139643745757152} NOTE: updated diags config
[Mar 19 16:21:20.956] Server {139643745757152} DEBUG: (cache_init) Store::read_config, fd = -1, "/usr/local/etc/trafficserver/storage.config"
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdb
"
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdb",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdb",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2064
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdb", O_RDONLY) = 7
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdb hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdb alignment = 0
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdc
"
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdc",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdc",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2080
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdc", O_RDONLY) = 7
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdc hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdc alignment = 0
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdd
"
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdd",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdd",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2096
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdd", O_RDONLY) = 7
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdd hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdd alignment = 0
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sde
"
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sde",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sde",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2112
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sde", O_RDONLY) = 7
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sde hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sde alignment = 0
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdf
"
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdf",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdf",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2128
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdf", O_RDONLY) = 7
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdf hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdf alignment = 0
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdg
"
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdg",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdg",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2144
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdg", O_RDONLY) = 7
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdg hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdg alignment = 0
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdh
"
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdh",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdh",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2160
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdh", O_RDONLY) = 7
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdh hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdh alignment = 0
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdi
"
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdi",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdi",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2176
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdi", O_RDONLY) = 7
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdi hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdi alignment = 0
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdj
"
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdj",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdj",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2192
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdj", O_RDONLY) = 7
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdj hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdj alignment = 0
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdk
"
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdk",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdk",-1)
[Mar 19 16:21:20.958] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2208
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdk", O_RDONLY) = 7
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdk hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdk alignment = 0
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdl
"
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdl",-1)
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdl",-1)
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2224
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdl", O_RDONLY) = 7
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdl hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdl alignment = 0
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdm
"
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdm",-1)
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdm",-1)
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2240
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdm", O_RDONLY) = 7
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdm hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdm alignment = 0
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdn
"
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdn",-1)
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdn",-1)
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2256
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdn", O_RDONLY) = 7
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdn hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdn alignment = 0
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdo
"
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdo",-1)
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdo",-1)
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2272
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdo", O_RDONLY) = 7
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdo hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdo alignment = 0
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.959] Server {139643745757152} NOTE: cache clustering disabled
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.ram_cache.size = -1 = 0Mb
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.limits.http.max_alts = 5
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) cache_config_ram_cache_cutoff = 4194304 = 4Mb
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.permit.pinning = 0
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.dir.sync_frequency = 60
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.vary_on_user_agent = 0
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.select_alternate = 1
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.max_doc_size = 0 = 0Mb
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.mutex_retry_delay = 2ms
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.config_dir = "/usr/local/etc/trafficserver"
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.url_hash_method = 1
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.max_disk_errors = 5
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.agg_write_backlog = 5242880
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.enable_checksum = 0
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.alt_rewrite_max_size = 4096
[Mar 19 16:21:20.959] Server {139643745757152} DEBUG: (cache_init) proxy.config.cache.enable_read_while_writer = 0
[Mar 19 16:21:20.960] Server {139643745757152} DEBUG: (cache_init) Store::read_config, fd = -1, "/usr/local/etc/trafficserver/storage.config"
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdb
"
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdb",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdb",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2064
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdb", O_RDONLY) = 7
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdb hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdb alignment = 0
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdc
"
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdc",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdc",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2080
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdc", O_RDONLY) = 7
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdc hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdc alignment = 0
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdd
"
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdd",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdd",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2096
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdd", O_RDONLY) = 7
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdd hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdd alignment = 0
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sde
"
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sde",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sde",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2112
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sde", O_RDONLY) = 7
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sde hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sde alignment = 0
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdf
"
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdf",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdf",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2128
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdf", O_RDONLY) = 7
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdf hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdf alignment = 0
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdg
"
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdg",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdg",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2144
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdg", O_RDONLY) = 7
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdg hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdg alignment = 0
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdh
"
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdh",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdh",-1)
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2160
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdh", O_RDONLY) = 7
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdh hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdh alignment = 0
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdi
"
[Mar 19 16:21:20.961] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdi",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdi",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2176
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdi", O_RDONLY) = 7
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdi hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdi alignment = 0
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdj
"
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdj",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdj",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2192
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdj", O_RDONLY) = 7
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdj hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdj alignment = 0
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdk
"
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdk",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdk",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2208
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdk", O_RDONLY) = 7
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdk hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdk alignment = 0
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdl
"
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdl",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdl",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2224
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdl", O_RDONLY) = 7
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdl hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdl alignment = 0
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdm
"
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdm",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdm",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2240
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdm", O_RDONLY) = 7
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdm hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdm alignment = 0
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdn
"
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdn",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdn",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2256
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdn", O_RDONLY) = 7
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdn hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdn alignment = 0
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Store::read_config: "/dev/sdo
"
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Store::read_config - ns = NEW (new Span); ns->init("/dev/sdo",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init("/dev/sdo",-1)
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFBLK - devnum = 2272
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/dev/sdo", O_RDONLY) = 7
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdo hw_sector_size = 512,is_disk = 1,adjusted_sec = 1
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init - /dev/sdo alignment = 0
[Mar 19 16:21:20.962] Server {139643745757152} DEBUG: (cache_init) Span::init physical sectors 1758109232 total size 900151926784 geometry size 900151926784 store blocks 109881827
[Mar 19 16:21:21.005] Server {139643745757152} DEBUG: (cache_init) Span::init("/usr/local/var/trafficserver",33554432)
[Mar 19 16:21:21.005] Server {139643745757152} DEBUG: (cache_init) Span::init - S_IFDIR - devnum = 64769
[Mar 19 16:21:21.005] Server {139643745757152} DEBUG: (cache_init) Span::init - socketManager.open("/usr/local/var/trafficserver", O_RDONLY) = 114
[Mar 19 16:21:21.005] Server {139643745757152} DEBUG: (cache_init) Span::init - is_disk = 0, raw device = no
[Mar 19 16:21:21.005] Server {139643745757152} DEBUG: (cache_init) Span::init - mapped file "/usr/local/var/trafficserver", 33554432
[Mar 19 16:21:21.006] Server {139643745757152} NOTE: cache clustering disabled
[Mar 19 16:21:21.110] Server {139643745757152} NOTE: logging initialized[7], logging_mode = 3
[Mar 19 16:21:21.118] Server {139643745757152} NOTE: traffic server running
[Mar 19 16:21:21.119] Server {139643745757152} DEBUG: (cache_init) Cache::open - proxy.config.cache.min_average_object_size = 8000
[Mar 19 16:21:21.121] Server {139643745757152} NOTE: reading directory '/dev/sdb 172032:109871104'
[Mar 19 16:21:21.124] Server {139643745757152} NOTE: reading directory '/dev/sdc 172032:109871104'
[Mar 19 16:21:21.126] Server {139643745757152} NOTE: reading directory '/dev/sdd 172032:109871104'
[Mar 19 16:21:21.128] Server {139643745757152} NOTE: reading directory '/dev/sde 172032:109871104'
[Mar 19 16:21:21.131] Server {139643745757152} NOTE: reading directory '/dev/sdf 172032:109871104'
[Mar 19 16:21:21.133] Server {139643745757152} NOTE: reading directory '/dev/sdg 172032:109871104'
[Mar 19 16:21:21.136] Server {139643745757152} NOTE: reading directory '/dev/sdh 172032:109871104'
[Mar 19 16:21:21.138] Server {139643745757152} NOTE: reading directory '/dev/sdi 172032:109871104'
[Mar 19 16:21:21.141] Server {139643745757152} NOTE: reading directory '/dev/sdj 172032:109871104'
[Mar 19 16:21:21.143] Server {139643745757152} NOTE: reading directory '/dev/sdk 172032:109871104'
[Mar 19 16:21:21.145] Server {139643745757152} NOTE: reading directory '/dev/sdl 172032:109871104'
[Mar 19 16:21:21.148] Server {139643745757152} NOTE: reading directory '/dev/sdm 172032:109871104'
[Mar 19 16:21:21.150] Server {139643745757152} NOTE: reading directory '/dev/sdn 172032:109871104'
[Mar 19 16:21:21.153] Server {139643745757152} NOTE: reading directory '/dev/sdo 172032:109871104'
[Mar 19 16:21:21.153] Server {139643745757152} NOTE: using directory B for '/dev/sdb 172032:109871104'
[Mar 19 16:21:21.153] Server {139643745757152} NOTE: using directory B for '/dev/sdc 172032:109871104'
[Mar 19 16:21:21.153] Server {139643745757152} NOTE: using directory B for '/dev/sdd 172032:109871104'
[Mar 19 16:21:21.153] Server {139643745757152} NOTE: using directory B for '/dev/sdf 172032:109871104'
[Mar 19 16:21:21.153] Server {139643745757152} NOTE: using directory B for '/dev/sdg 172032:109871104'
[Mar 19 16:21:21.153] Server {139643745757152} NOTE: using directory B for '/dev/sde 172032:109871104'
[Mar 19 16:21:21.153] Server {139643745757152} NOTE: using directory A for '/dev/sdh 172032:109871104'
[Mar 19 16:21:21.153] Server {139643745757152} NOTE: using directory A for '/dev/sdm 172032:109871104'
[Mar 19 16:21:21.154] Server {139643745757152} NOTE: using directory A for '/dev/sdj 172032:109871104'
[Mar 19 16:21:21.157] Server {139643745757152} NOTE: using directory B for '/dev/sdn 172032:109871104'
[Mar 19 16:21:21.159] Server {139643745757152} NOTE: using directory B for '/dev/sdk 172032:109871104'
[Mar 19 16:21:21.160] Server {139643745757152} NOTE: using directory A for '/dev/sdi 172032:109871104'
[Mar 19 16:21:21.163] Server {139643745757152} NOTE: using directory B for '/dev/sdo 172032:109871104'
[Mar 19 16:21:21.164] Server {139643745757152} NOTE: using directory A for '/dev/sdl 172032:109871104'
[Mar 19 16:24:14.604] Server {139643693561600} NOTE: recovery clearing offsets [619465613312, 619476951040] sync_serial 56 next 57
[Mar 19 16:24:19.612] Server {139643692508928} NOTE: recovery clearing offsets [619439356416, 619450399232] sync_serial 56 next 57
[Mar 19 16:24:20.583] Server {139643690403584} NOTE: recovery clearing offsets [622551635456, 622562514432] sync_serial 66 next 67
[Mar 19 16:24:21.687] Server {139643676718848} NOTE: recovery clearing offsets [621158816768, 621172087808] sync_serial 65 next 66
[Mar 19 16:24:23.803] Server {139643671455488} NOTE: recovery clearing offsets [619182073856, 619199670272] sync_serial 65 next 66
[Mar 19 16:24:24.066] Server {139643674613504} NOTE: recovery clearing offsets [621827118592, 621839734272] sync_serial 57 next 58
[Mar 19 16:24:24.194] Server {139643688298240} NOTE: recovery clearing offsets [618844670464, 618855385600] sync_serial 61 next 62
[Mar 19 16:24:24.547] Server {139643681982208} NOTE: recovery clearing offsets [621682653696, 621696285184] sync_serial 57 next 58
[Mar 19 16:24:25.069] Server {139643684087552} NOTE: recovery clearing offsets [621340225024, 621350809088] sync_serial 57 next 58
[Mar 19 16:24:25.297] Server {139643665139456} NOTE: recovery clearing offsets [619561203712, 619576190976] sync_serial 60 next 61
[Mar 19 16:24:25.400] Server {139643668297472} NOTE: recovery clearing offsets [619941993472, 619954772992] sync_serial 58 next 59
[Mar 19 16:24:26.393] Server {139643669350144} NOTE: recovery clearing offsets [621103206400, 621116575744] sync_serial 57 next 58
[Mar 19 16:24:26.501] Server {139643683034880} NOTE: recovery clearing offsets [619102690816, 619111079424] sync_serial 61 next 62
[Mar 19 16:24:26.507] Server {139643670402816} NOTE: recovery clearing offsets [621573930496, 621587398144] sync_serial 61 next 62
[Mar 19 16:24:32.195] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - theCache, total_size = 1538195456 = 12017152 MB
[Mar 19 16:24:32.195] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - caches_ready=0x3, gnvol=14
[Mar 19 16:24:32.195] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - cache_config_ram_cache_size == AUTO_SIZE_RAM_CACHE
[Mar 19 16:24:32.195] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 1122312192 = 1070Mb
[Mar 19 16:24:32.195] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 898941771776 = 857297Mb
[Mar 19 16:24:32.434] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 2244624384 = 2140Mb
[Mar 19 16:24:32.434] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 1797883543552 = 1714595Mb
[Mar 19 16:24:32.610] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 3366936576 = 3210Mb
[Mar 19 16:24:32.610] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 2696825315328 = 2571893Mb
[Mar 19 16:24:32.743] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 4489248768 = 4281Mb
[Mar 19 16:24:32.743] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 3595767087104 = 3429190Mb
[Mar 19 16:24:32.920] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 5611560960 = 5351Mb
[Mar 19 16:24:32.920] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 4494708858880 = 4286488Mb
[Mar 19 16:24:33.074] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 6733873152 = 6421Mb
[Mar 19 16:24:33.074] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 5393650630656 = 5143786Mb
[Mar 19 16:24:33.207] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 7856185344 = 7492Mb
[Mar 19 16:24:33.207] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 6292592402432 = 6001083Mb
[Mar 19 16:24:33.374] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 8978497536 = 8562Mb
[Mar 19 16:24:33.374] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 7191534174208 = 6858381Mb
[Mar 19 16:24:33.507] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 10100809728 = 9632Mb
[Mar 19 16:24:33.507] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 8090475945984 = 7715679Mb
[Mar 19 16:24:33.640] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 11223121920 = 10703Mb
[Mar 19 16:24:33.640] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 8989417717760 = 8572976Mb
[Mar 19 16:24:33.812] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 12345434112 = 11773Mb
[Mar 19 16:24:33.812] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 9888359489536 = 9430274Mb
[Mar 19 16:24:33.993] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 13467746304 = 12843Mb
[Mar 19 16:24:33.993] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 10787301261312 = 10287572Mb
[Mar 19 16:24:34.157] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 14590058496 = 13914Mb
[Mar 19 16:24:34.157] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 11686243033088 = 11144869Mb
[Mar 19 16:24:34.334] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 15712370688 = 14984Mb
[Mar 19 16:24:34.334] Server {139643688298240} DEBUG: (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 12585184804864 = 12002167Mb
[Mar 19 16:24:34.511] Server {139643688298240} NOTE: cache enabled
top -H -b partial output when this is happening:
top - 16:22:28 up 6 days, 21:11, 3 users, load average: 0.68, 0.59, 0.46
Tasks: 608 total, 16 running, 592 sleeping, 0 stopped, 0 zombie
Cpu(s): 2.5%us, 51.6%sy, 0.0%ni, 45.9%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 148835736k total, 31720652k used, 117115084k free, 207704k buffers
Swap: 4194296k total, 0k used, 4194296k free, 12297584k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
31370 ats 20 0 16.5g 15g 4220 R 99.2 10.6 1:00.16 [ET_NET 14]
31383 ats 20 0 16.5g 15g 4220 R 99.2 10.6 0:59.78 [ET_NET 27]
31362 ats 20 0 16.5g 15g 4220 R 98.8 10.6 1:00.70 [ET_NET 6]
31364 ats 20 0 16.5g 15g 4220 R 98.8 10.6 1:00.28 [ET_NET 8]
31375 ats 20 0 16.5g 15g 4220 R 98.8 10.6 1:00.16 [ET_NET 19]
31381 ats 20 0 16.5g 15g 4220 R 98.8 10.6 0:59.94 [ET_NET 25]
31386 ats 20 0 16.5g 15g 4220 R 98.8 10.6 0:59.58 [ET_NET 30]
31359 ats 20 0 16.5g 15g 4220 R 98.5 10.6 1:01.16 [ET_NET 3]
31377 ats 20 0 16.5g 15g 4220 R 98.5 10.6 0:59.91 [ET_NET 21]
31360 ats 20 0 16.5g 15g 4220 R 98.2 10.6 1:00.99 [ET_NET 4]
31369 ats 20 0 16.5g 15g 4220 R 97.5 10.6 1:00.17 [ET_NET 13]
31368 ats 20 0 16.5g 15g 4220 R 97.2 10.6 1:00.25 [ET_NET 12]
31380 ats 20 0 16.5g 15g 4220 R 97.2 10.6 1:00.00 [ET_NET 24]
31382 ats 20 0 16.5g 15g 4220 R 97.2 10.6 0:59.65 [ET_NET 26]
101 root 20 0 0 0 0 S 0.3 0.0 0:23.55 events/2
24980 jvando00 20 0 96340 1692 776 S 0.3 0.0 0:00.20 sshd
31389 ats 20 0 16.5g 15g 4220 S 0.3 10.6 0:00.03 [ET_NET 33]
31392 ats 20 0 16.5g 15g 4220 S 0.3 10.6 0:00.06 [STAT_SYNC]
31507 ats 20 0 16.5g 15g 4220 S 0.3 10.6 0:00.09 [ET_UDP 0]
31513 jvando00 20 0 13532 1536 856 R 0.3 0.0 0:00.05 top
Re: Trafficserver startup.
Posted by Leif Hedstrom <zw...@apache.org>.
On 3/20/12 12:48 PM, Van Doorn, Jan R wrote:
> Hi,
>
> When I startup trafficserver, I takes about 3-4 minutes for it to say
> "NOTE: cache enabled". In that time, the cache is serving requests, but
> it's not writing to the cache, the CPU usage is very high (E_NET threads),
> and sometimes clients will hang when they try to get data from/through the
> cache.
>
> Is this normal? Should I wait with redirecting traffic to the cache until
> i get this ""NOTE: cache enabled" message? I am using 3.0.2 on a pretty
> beefy new box with ~11TB of cache over 14 spindles.
>
Probably as expected. 11TB, with the default settings of one directory entry
(or "object") per 8,000 bytes means 1,511,828,488 entries. That's 1.5
billion entries... It has to read and load all that information into memory
before it can serve out of cache.
Is the expectation really to hold 1.5 billion entries in the cache ? If not,
you should adjust the configuration accordingly. That will not only speed up
startup times, but also reduce memory consumption (that 1.5B entries would
consume a lot of RAM, like probably 20GB or so). So, if you set it to say
64KB, you could hold "only"~ 400 million objects in the cache, but would
reduce RAM and startup time by a factor of 4.
-- Leif