Solaris Extended Accounting in the Real World
Posted on October 21, 2009
Recently we talked about Solaris Auditing (BSM) in the Real World. Like BSM, Extended Accounting is a fantastic feature of Solaris that is utterly useless without tools. Solaris goes so far as giving you the capability but not so far as to hand you the rest of the solution on a silver platter. On one hand this means that the technology isn’t pigeon holed due to the capabilities of a single tool, but at the same time it creates a barrier to entry that causes many people to simply ignore it all together. So, yet again, let me provide a simple tool to fill some of that void.
In a previous post, Solaris Extended Accounting, I described Extended Accounting and provided two scripts to get you started, one was a PERL script to dump Extended Accounting (“exacct”) data files and the other was called “prettyproc” which output Proccess Accounting files in a more human friendly way. This post should be viewed as Part 2 of that post.
When & How to use Extended Accounting
The most basic explanation of Extended Accounting is this: a facility that records certain events upon completion for later analysis. Those certain events depend on which of the four accounting types we’re using. For processes, the cumulative data maintained by Solaris microstate accounting is written into a single record as process termination. For tasks, which are groups of processes within a single project, the same applies but recorded on each task termination rather than process. For (Crossbow) net, aggregate network utilization is written out on regular intervals (15 seconds). We’ll ignore IPQoS “flow” Accounting entirely for the time being.
So the first thing we should say is that Extended Accounting is not a monitoring facility. If you want to know how much CPU or Memory is being used at some given time you should rely upon Kstats or /proc statistics on a polling schedule.
What Extended Accounting is good for is reporting. Consider ‘net’ accounting; every 15 seconds a record is created for each data link (dladm show-link). You could easily create a report at some interval (hour, day, week, month?) for both total bytes/packets sent/recieved on each link or great a graph or perhaps most likely calculate 95th percentile on the links. Now, in this case of ‘net’ accounting you could also use an external system to poll the data remotely via SNMP or locally via kstats, but this might serve as a better “definiative” local record.
Proc accounting is fuzzy ground though. The best way I can explain process accounting is to imagine that every time you executed a command Solaris was secretly running “time(1M)” and then storing the output on your behalf.
benr@quadra Downloads$ time tar xfj flash_player_10_solaris_x86.tar.bz2 real 0m0.763s user 0m0.705s sys 0m0.070s
This is, essentially, whats happening! Solaris maintains a lot of detail on what processes are doing (known as “microstate accounting”). Normally, when a process terminates that data is simply discarded, however if Process Extended Accounting is enabled its dumped out as a record! From this record we can see interesting stats such as when the process started, when it finished (real time), how long it spent cpu time in kernel-land (sys time), how long it spent cpu time in user-land (user time), how many context switches it made, how much swapping it did, what its average RSS memory usage was, etc, etc, etc.
But as wonderful as this is, I have to make it crystal clear that this data isn’t written out untill a process terminates! If MySQL runs for 4 months, it outputs a single record when it was finally shut down, and that record is the accumulation of that full 4 months of running!
Here is the exception. Proc and Task records can be “full” or “partial”. When a process/task terminates and creates a record, that’s a “full record”. However, using “wracct” we can force a process or task to create a “partial record”, which is essentially a way of saying “Just tell me what you’ve got so far!” The rub is that, in the proc case, that data is cumulative, so if you wanted to report on what a process has done in the last 24 hours you need to write a partial record every 24 hours and the find the difference between the partial record yesterday and partial record today. Talk about fun.
Now, besides all that, who actually bills users or reports usage based on total CPU time? Total context switches? This isn’t the 1970’s nor is this likely to be a Super Computer reporting computational time. In short, the data probably isn’t terribly useful as a basis for billing in this day and age without some creative thought.
So then lets think… what can we determine from the data. Based on CPU usage we could determine what the top 5 CPU consuming processes were. Based on average RSS usage we could determine what the top memory consumers were. So on and so forth. Interesting perhaps… but worth it?
Go back to what I said about running “time” on every command. This data could be of used for capacity planning or, with some intelligence, behavior monitoring. Are your users complaining about commands taking too long to run, but when you ask how long they give you a bogus number or simply shrug? Extended Accounting can tell you. Are batch jobs running at night but want a record of when they started and how resource hungry they were? Here is a way that doesn’t involve writing wrappers!
In short, Extended Accounting is a pretty lousy billing system on todays mulit-core systems, but it can provide useful historical statistics to questions that might be otherwise difficult to answer.
The first tool I’ll provide you with is a PERL replacement for the Solaris included /usr/demo/libexacct/exdump.c: exdebug.pl. This tool offers the following advantages:
- exdump.c hasn’t been updated for the new Crossbow provided ‘net’ accounting data; exdebug.pl is module agnostic and works with them all.
- The output is just much cleaner and intuitive for exploring what ExAcct can do for you.
- Its implemented in PERL making it easier to get in there and build something, rather than dealing with the libexacct learning curve in C. If nothing else you can quickly prototype and then re-implement in C.
Here is an example from an ‘net’ record:
benr@quadra exacct$ acctadm net Net accounting: active Net accounting file: /var/adm/exacct/net Tracked net resources: extended Untracked net resources: none benr@quadra exacct$ pfexec ./exdebug.pl /var/adm/exacct/net | more Creator: SunOS Hostname: quadra ---------------- OBJECT 0 ----------------------- Object is: EO_GROUP - Catalog: EXT_GROUP EXC_DEFAULT EXD_GROUP_NET_LINK_DESC Id: EXD_NET_DESC_NAME Value: testzone0 Id: EXD_NET_DESC_EHOST Value: Id: EXD_NET_DESC_EDEST Value: Id: EXD_NET_DESC_VLAN_TPID Value: 0 Id: EXD_NET_DESC_VLAN_TCI Value: 0 Id: EXD_NET_DESC_SAP Value: 0 Id: EXD_NET_DESC_PRIORITY Value: 0 Id: EXD_NET_DESC_BWLIMIT Value: 0 Id: EXD_NET_DESC_DEVNAME Value: testzone0 Id: EXD_NET_DESC_V4SADDR Value: 0 Id: EXD_NET_DESC_V4DADDR Value: 0 Id: EXD_NET_DESC_SPORT Value: 0 Id: EXD_NET_DESC_DPORT Value: 0 Id: EXD_NET_DESC_PROTOCOL Value: 0 Id: EXD_NET_DESC_DSFIELD Value: 0 ... ---------------- OBJECT 67 ----------------------- Object is: EO_GROUP - Catalog: EXT_GROUP EXC_DEFAULT EXD_GROUP_NET_LINK_STATS Id: EXD_NET_STATS_NAME Value: e1000g1 Id: EXD_NET_STATS_CURTIME Value: 1256033841 Id: EXD_NET_STATS_IBYTES Value: 2411692067 Id: EXD_NET_STATS_OBYTES Value: 202604900 Id: EXD_NET_STATS_IPKTS Value: 2005669 Id: EXD_NET_STATS_OPKTS Value: 1265178 Id: EXD_NET_STATS_IERRPKTS Value: 0 Id: EXD_NET_STATS_OERRPKTS Value: 0 ---------------- OBJECT 68 ----------------------- Object is: EO_GROUP - Catalog: EXT_GROUP EXC_DEFAULT EXD_GROUP_NET_FLOW_STATS Id: EXD_NET_STATS_NAME Value: inbound_ssh Id: EXD_NET_STATS_CURTIME Value: 1256033841 Id: EXD_NET_STATS_IBYTES Value: 93958770 Id: EXD_NET_STATS_OBYTES Value: 106077944 Id: EXD_NET_STATS_IPKTS Value: 238395 Id: EXD_NET_STATS_OPKTS Value: 321977 Id: EXD_NET_STATS_IERRPKTS Value: 0 Id: EXD_NET_STATS_OERRPKTS Value: 0 ---------------- OBJECT 69 ----------------------- Object is: EO_GROUP - Catalog: EXT_GROUP EXC_DEFAULT EXD_GROUP_NET_LINK_STATS Id: EXD_NET_STATS_NAME Value: testzone0 Id: EXD_NET_STATS_CURTIME Value: 1256033861 Id: EXD_NET_STATS_IBYTES Value: 4528169 Id: EXD_NET_STATS_OBYTES Value: 0 Id: EXD_NET_STATS_IPKTS Value: 64405 Id: EXD_NET_STATS_OPKTS Value: 0 Id: EXD_NET_STATS_IERRPKTS Value: 0 Id: EXD_NET_STATS_OERRPKTS Value: 0
In the above example you’ll see the variety of objects offered by the net accounting module, including link descriptions, link statistics (‘testzone0’ is a VNIC and ‘e1000g1’ is a physical interface), and flow statistics (inbound_ssh is a flowadm defined flow).
The second tool is exacctly, a human friendly Proc Extended Accounting dumper. It is also implemented in PERL and in fact was derived from the exdebug app above.
benr@quadra exacct$ acctadm proc Process accounting: active Process accounting file: /var/adm/exacct/proc Tracked process resources: extended Untracked process resources: host benr@quadra exacct$ pfexec ./exacctly /var/adm/exacct/proc | more Creator: SunOS Hostname: quadra ZONE UID GID PID CMD | Real User Sys | Start Date | RSS AVG RSS MAX SysCalls Swaps ----------------------------------------------------+--------------------------+--------------------------+-------------------------------------------------- global 0 0 1922 acctadm | 0.07 0.00 0.01 | Tue Oct 20 03:10:01 2009 | 524 K 12904 K 450 0 | FULL global 0 0 1920 sh | 0.07 0.00 0.00 | Tue Oct 20 03:10:01 2009 | 2036 K 12904 K 103 0 | FULL global 25 25 1924 sendmail | 0.10 0.01 0.01 | Tue Oct 20 03:10:01 2009 | 1912 K 12904 K 543 0 | FULL global 0 0 1927 sendmail | 0.01 0.00 0.01 | Tue Oct 20 03:10:01 2009 | 2288 K 13172 K 267 0 | FULL global 0 0 1923 mail | 0.10 0.00 0.00 | Tue Oct 20 03:10:01 2009 | 504 K 12904 K 169 0 | FULL global 0 0 1921 sh | 0.11 0.00 0.00 | Tue Oct 20 03:10:01 2009 | 920 K 12904 K 102 0 | FULL
The output is really wide, but everyone should have a big ol’ screen these days. Notice the depth of information here. For each terminated process we see the zone it was in, user and group, PID and command name itself (ExAcct doesn’t record arguments), then we see real/sys/user time in seconds (ExAcct actually has nanosecond granularity, so these are rounded numbers), the start time and other goodness. The last column reports whether the record is full or partial.
This tool is, in and of itself, useful for many administrators to start using Extended Accounting that might otherwise have ignored it. Even more so, I hope it sparks your interest and imagination as to the possibilities! Just think of all the ways to amaze your boss and fellow admins!
Data File Rotation
Like any log, don’t be lazy and forget to rotate those files or you’ll have a mess on your hands. Rotating your extended accounting data files will make them easier to dissect and consume less disk. Here are some examples lines you can drop into /etc/logadm.conf, Solaris’s default log rotation tool:
/var/adm/exacct/proc -N -p 1d -C 7 -b '/usr/sbin/acctadm -x process' -a '/usr/sbin/acctadm -e extended -f /var/adm/exacct/proc process' /var/adm/exacct/net -N -p 1d -C 7 -b '/usr/sbin/acctadm -x net' -a '/usr/sbin/acctadm -e extended -f /var/adm/exacct/net net' /var/adm/exacct/task -N -p 1d -C 7 -b '/usr/sbin/acctadm -x task' -a '/usr/sbin/acctadm -e extended -f /var/adm/exacct/task task'
These examples will rotate each day (-p 1d) and keep 7 logs (-C 7) before destroying. The important bit is that you can’t just mv the file, you need to stop accounting, rotate, then resume it.
Remember to ensure that logadm isn’t commented out in the root crontab.
Parting Thoughts & Cautions
Before I wrap up, I want to note something about Process records. Here is one as seen with exdebug:
---------------- OBJECT 0 ----------------------- Object is: EO_GROUP - Catalog: EXT_GROUP EXC_DEFAULT EXD_GROUP_PROC Id: EXD_PROC_PID Value: 1922 Id: EXD_PROC_UID Value: 0 Id: EXD_PROC_GID Value: 0 Id: EXD_PROC_PROJID Value: 1 Id: EXD_PROC_TASKID Value: 39949 Id: EXD_PROC_CPU_USER_SEC Value: 0 Id: EXD_PROC_CPU_USER_NSEC Value: 2047013 Id: EXD_PROC_CPU_SYS_SEC Value: 0 Id: EXD_PROC_CPU_SYS_NSEC Value: 6237135 Id: EXD_PROC_START_SEC Value: 1256033401 Id: EXD_PROC_START_NSEC Value: 311640743 Id: EXD_PROC_FINISH_SEC Value: 1256033401 Id: EXD_PROC_FINISH_NSEC Value: 380283918 Id: EXD_PROC_COMMAND Value: acctadm Id: EXD_PROC_TTY_MAJOR Value: 4294967295 Id: EXD_PROC_TTY_MINOR Value: 4294967295 Id: EXD_PROC_FAULTS_MAJOR Value: 0 Id: EXD_PROC_FAULTS_MINOR Value: 0 Id: EXD_PROC_MESSAGES_SND Value: 0 Id: EXD_PROC_MESSAGES_RCV Value: 0 Id: EXD_PROC_BLOCKS_IN Value: 0 Id: EXD_PROC_BLOCKS_OUT Value: 0 Id: EXD_PROC_CHARS_RDWR Value: 20100 Id: EXD_PROC_CONTEXT_VOL Value: 102 Id: EXD_PROC_CONTEXT_INV Value: 0 Id: EXD_PROC_SIGNALS Value: 0 Id: EXD_PROC_SWAPS Value: 0 Id: EXD_PROC_SYSCALLS Value: 450 Id: EXD_PROC_ACCT_FLAGS Value: 2 Id: EXD_PROC_ANCPID Value: 1920 Id: EXD_PROC_WAIT_STATUS Value: 0 Id: EXD_PROC_ZONENAME Value: global Id: EXD_PROC_MEM_RSS_AVG_K Value: 524 Id: EXD_PROC_MEM_RSS_MAX_K Value: 12904
Okey, lots of data, lots of goodness. Notice EXD_PROC_BLOCKS_IN, OUT, and CHARS_RDWR? They are useless. I can’t go into why here, but don’t get excited about them or bother doing anything, the values are crap. If your a veteran Kstat diver you’ll recognize similar values in the Kstat cpu_stat class… same story.
Hopefully this post as helped provide you with a more practical understanding of Extended Accounting and provided you with some resources to get in there and use the data. There is a wealth of possibilities if you just avail yourself of them. 🙂