Problem case: AIX 6.1 system paging space writes in spite of sufficient free memory

I wanted to share some statistics from a few systems to show that some AIX memory management conditions are extremely difficult to understand without access to information about the amount of free memory in each of the memory pools.  Although there are ways to get this information from kdb... using kdb for monitoring doesn't seem like a great idea if there is an alternative.  Secondly, since root privileges are required to run kdb... it has to be root that runs the collection script.  I'd really like for this information to be included in something like vmstat output... but I've got to justify the value of such an enhancement. 

So I'll create a few posts with some of the numbers I've grabbed from various systems.  Places where page out to paging space is occurring, even though there sure seems like sufficient free server memory to prevent lrud from paging contents to paging space. 

Its true that there isn't much tuning that can be performed when you see that paging is due to imbalanced use of the memory pools.  But administrators don't just use systems stats for tuning feedback.  Sometimes its to diagnose a defect for which a fix is already available.  Sometimes the stats are used to get some more attention in a PMR to a condition that is likely a bug, and might be dismissed as application behavior or misconfiguration otherwise.  (I suspect that the defect fixed by recent AIX 6.1 TL6 APAR IV28494 and effecting all TLs up to AIX 7.1 TL2 could have been found and fixed a lot earlier if the pool level information could be retrieved in a less arcane manner. http://sql-sasquatch.blogspot.com/2013/08/ibm-fixes-minor-enhanced-affinity-bug.html)  Retrieving stats from the memory pool level can also build leverage for disabling memory_affinity when it would be beneficial - even though the general recommendation is to keep memory_affinity enabled in spite of memory pool imbalance.

Here's some information from a Power6 system that I gathered months ago.

[sasquatch@mtnhome] $ oslevel -s

6100-08-02-1316 

[sasquatch@mtnhome] $ lssrad -av

REF1   SRAD        MEM      CPU

0

          0   23767.31      0-19

[root@mtnhome] # echo "mempool *" |kdb
           START              END <name>
0000000000001000 0000000004160000 start+000FD8
F00000002FF47600 F00000002FFDF9C8 __ublock+000000
000000002FF22FF4 000000002FF22FF8 environ+000000
000000002FF22FF8 000000002FF22FFC errno+000000
F1000F0A00000000 F1000F0A10000000 pvproc+000000
F1000F0A10000000 F1000F0A18000000 pvthread+000000
read vscsi_scsi_ptrs OK, ptr = 0x0
(0)> mempool *
                 VMP MEMP  NB_PAGES  FRAMESETS        NUMFRB
F1000F0009740000  00  000   0023D7F0  000 001 002 003 000384E7
F1000F0009740500  00  001   0023C280  004 005 006 007 000375B0
F1000F0009740A00  01  002   000AB300  008 009 00A 00B 0001B078
F1000F0009740F00  02  003   000AB300  00C 00D 00E 00F 00012D57
 
(0)> 

So I've got two virtual memory pools, each with two memory pools.

Memory pool 001 has 2349040 4k frames and pool 002 has 2343552 4k frames - approximately 8.96 GB and 8.94 GB respectively.

Pools 002 and 003 each have 701184 4k frames - approximately 2.67 GB each.

Since the time I gathered the information above, I've switched to using the frs subcommand for these investigations.  Having the breakdown between 4k and 64k pages is especially useful.  But the decimal conversion for the free frames in each frameset is especially helpful in of-the-moment support situations.

Here's the real guts of the numbers.  Its 5:00 am to 5:40 am, with two instance of vmstat collecting information in 15 second intervals.  One instance is collecting 4k page info, the other instance collecting 64k info (that's why I've even included he two timestamps below).

Some observations:

With default minfree in place, if server memory was being used without regard to which pool its in, we wouldn't expect to see page outs of 4k pages unless the free list falls below 4 * 960 = 3840, since there are 4 pools and lrud looks at each pool freelist for the minfree threshold.

From 5:30:13 to 5:36:13, vmstat indicates at least 8682 4k pages on the freelist and at least 500 64k pages on the freelist.  But there was significant pageout activity.From 5:38:58 to 5:40:43 there were at least 9506 4k pages in the freelist and at least 588 64k pages in the freelist.  But there was significant pageout activity.

Now, at the time that I gathered this information, I didn't have my monitor written to grab information from kdb in regular intervals.  But I strongly suspected that the memory pool imbalance was problematic.

There's only one other explanation that I can think of... microbursts of memory activity, where the freelists are dipping below the minfree threshold for such a small time that the 15 second averages look they should have stayed above minfree the whole time.  I'm sure that happens sometimes... but I'm also positive that it doesn't happen frequently enough to be behind all of the examples I've seen.

time4k	avm4k	fre4k	po4k	pi4k	time64k	siz64k	avm64k	fre64k	po64k	pi64k
5:00:12	4479677	1536267	0	0	5:00:13	146351	145536	815	0	0
5:00:27	4498516	1517192	0	2	5:00:28	146351	145556	795	0	0
5:00:42	4470942	1544745	0	0	5:00:43	146351	145560	791	0	0
5:00:57	4479972	1535693	0	0	5:00:58	146351	145560	791	0	0
5:01:12	4451605	1561740	0	0	5:01:13	146351	145540	811	0	0
5:01:27	4451606	1561727	0	0	5:01:28	146351	145540	811	0	0
5:01:42	4478956	1531924	0	0	5:01:43	146351	145580	771	0	0
5:01:57	4520184	1490667	0	0	5:01:58	146351	145620	731	0	0
5:02:12	4490547	1520289	0	0	5:02:13	146351	145610	741	0	0
5:02:27	4490555	1520262	0	0	5:02:28	146351	145610	741	0	0
5:02:42	4490562	1520239	0	0	5:02:43	146351	145610	741	0	0
5:02:57	4489768	1518583	0	0	5:02:58	146351	145620	731	0	0
5:03:12	4501919	1506416	0	0	5:03:13	146351	145625	726	0	0
5:03:27	4488049	1517839	0	0	5:03:28	146351	145620	731	0	0
5:03:42	4464548	1541320	0	0	5:03:43	146351	145615	736	0	0
5:03:57	4386328	1619525	0	0	5:03:58	146351	145625	726	0	0
5:04:12	4391810	1614029	0	0	5:04:13	146351	145625	726	0	0
5:04:27	4416017	1589805	0	0	5:04:28	146351	145615	736	0	0
5:04:42	4366296	1637076	0	0	5:04:43	146351	145612	739	0	0
5:04:57	4403652	1599700	0	0	5:04:58	146351	145627	724	0	0
5:05:12	4409458	1593879	0	0	5:05:13	146351	145627	724	0	0
5:05:27	4419552	1583769	0	0	5:05:28	146351	145616	735	0	0
5:05:42	4429782	1571079	0	0	5:05:43	146351	145632	719	0	0
5:05:57	4612693	1388153	0	0	5:05:58	146351	145851	500	0	0
5:06:12	4697491	1303332	0	0	5:06:13	146415	145927	488	0	0
5:06:27	4809394	1191409	0	0	5:06:28	146415	145927	488	0	0
5:06:42	4862231	1138485	0	0	5:06:43	146415	145917	498	0	0
5:06:57	4995781	1004911	0	0	5:06:58	146415	145913	502	0	0
5:07:12	5039214	961462	0	0	5:07:13	146415	145923	492	0	0
5:07:27	5183831	816828	0	0	5:07:28	146479	146003	476	0	0
5:07:42	5470116	530524	0	0	5:07:43	146479	145993	486	0	0
5:07:57	5796571	201577	0	0	5:07:58	146479	145993	486	0	0
5:08:12	6005278	12297	0	0	5:08:13	146479	146003	476	0	0
5:08:27	6116575	9595	0	0	5:08:28	146479	146003	476	0	0
5:08:42	6280564	10865	223	16	5:08:43	146479	146014	465	0	0
5:08:57	6427583	12747	3633	51	5:08:59	146479	146014	465	0	0
5:09:12	6565990	7375	5563	79	5:09:14	146479	146024	455	0	0
5:09:27	6626389	11171	4776	513	5:09:29	146479	146027	452	0	0
5:09:42	6659459	12307	2335	137	5:09:44	146479	146026	453	0	0
5:09:57	6706790	7293	2878	165	5:09:59	146479	146026	453	0	0
5:10:12	6767226	12054	4366	114	5:10:14	146479	146036	443	0	0
5:10:27	6605343	168827	353	179	5:10:29	146479	146036	443	0	0
5:10:42	6352312	418607	0	87	5:10:44	146479	146030	449	0	0
5:10:58	6331056	439211	0	47	5:10:59	146479	146019	460	0	0
5:11:13	6345507	423647	0	69	5:11:14	146479	146029	450	0	0
5:11:28	6348486	417263	0	48	5:11:29	146479	146029	450	0	0
5:11:43	6333264	430940	0	70	5:11:44	146479	146008	471	0	0
5:11:58	6333464	429803	0	59	5:11:59	146479	146003	476	0	0
5:12:13	6330497	432209	0	35	5:12:14	146479	146008	471	0	0
5:12:28	6412141	346997	0	71	5:12:29	146479	146007	472	0	0
5:12:43	6242615	512923	0	62	5:12:44	146479	145997	482	0	0
5:12:58	6225206	526757	0	74	5:12:59	146479	145958	521	0	0
5:13:13	6005319	739394	0	111	5:13:14	146479	145959	520	0	0
5:13:28	5889966	845417	0	52	5:13:29	146479	145954	525	0	0
5:13:43	5865012	869598	0	49	5:13:44	146479	145923	556	0	0
5:13:58	5864547	869608	0	28	5:13:59	146479	145922	557	0	0
5:14:13	5869100	863449	0	45	5:14:14	146479	145937	542	0	0
5:14:28	5906781	822685	0	29	5:14:29	146479	145947	532	0	0
5:14:43	5942513	786157	0	36	5:14:44	146479	145992	487	0	0
5:14:58	6072666	652280	0	27	5:14:59	146607	146151	456	0	0
5:15:13	6364199	360084	0	18	5:15:14	146735	146263	472	0	0
5:15:28	6183692	538880	0	39	5:15:29	146735	146237	498	0	0
5:15:43	6167569	554702	0	11	5:15:44	146735	146221	514	0	0
5:15:58	6144623	577429	0	9	5:15:59	146735	146215	520	0	0
5:16:13	6238689	482966	0	24	5:16:14	146735	146216	519	0	0
5:16:28	6275805	445741	0	5	5:16:29	146735	146214	521	0	0
5:16:43	6276013	445421	0	6	5:16:44	146735	146204	531	0	0
5:16:58	6101668	619137	0	30	5:16:59	146735	146194	541	0	0
5:17:13	6002164	715473	0	8	5:17:14	146735	146200	535	0	0
5:17:28	6021171	696197	0	14	5:17:29	146735	146200	535	0	0
5:17:43	6038452	675896	0	12	5:17:44	146735	146187	548	0	0
5:17:58	6017389	696735	0	13	5:17:59	146735	146196	539	0	0
5:18:13	6001791	712107	0	13	5:18:14	146735	146215	520	0	0
5:18:28	6100299	613431	0	9	5:18:29	146735	146220	515	0	0
5:18:43	6079615	633971	0	7	5:18:44	146735	146221	514	0	0
5:18:58	6041705	669336	0	5	5:18:59	146735	146210	525	0	0
5:19:13	6054484	656472	0	4	5:19:14	146735	146218	517	0	0
5:19:28	6169205	541487	0	13	5:19:29	146735	146223	512	0	0
5:19:43	6163877	544229	0	8	5:19:44	146735	146208	527	0	0
5:19:58	6109669	598314	0	6	5:19:59	146735	146203	532	0	0
5:20:13	6114987	592856	0	5	5:20:14	146735	146214	521	0	0
5:20:28	6112390	594749	0	10	5:20:29	146735	146208	527	0	0
5:20:43	6001914	704665	0	4	5:20:44	146735	146223	512	0	0
5:20:58	5979428	724528	0	10	5:20:59	146735	146173	562	0	0
5:21:13	5910642	791703	0	7	5:21:14	146735	146019	716	0	0
5:21:28	5889066	813092	0	9	5:21:29	146735	146019	716	0	0
5:21:43	5883143	816444	0	7	5:21:44	146735	146009	726	0	0
5:21:58	5876343	823175	0	2	5:21:59	146735	145999	736	0	0
5:22:13	5805146	881064	0	57	5:22:14	146735	145849	886	0	0
5:22:28	5814261	871760	0	10	5:22:29	146735	145849	886	0	0
5:22:43	5807678	875856	0	2	5:22:44	146735	145843	892	0	0
5:22:58	5808963	874398	0	4	5:22:59	146735	145839	896	0	0
5:23:13	5813056	870219	0	2	5:23:14	146735	145849	886	0	0
5:23:28	5818436	864699	0	8	5:23:29	146735	145849	886	0	0
5:23:43	5913180	769803	0	8	5:23:44	146735	145839	896	0	0
5:23:58	5869600	810909	0	1	5:23:59	146735	145759	976	0	0
5:24:13	5874825	805585	0	5	5:24:14	146735	145769	966	0	0
5:24:28	5876120	804175	0	6	5:24:29	146735	145769	966	0	0
5:24:43	5870572	807217	0	3	5:24:44	146735	145759	976	0	0
5:24:58	5870165	807600	0	0	5:24:59	146735	145759	976	0	0
5:25:13	5874069	803290	0	2	5:25:14	146735	145764	971	0	0
5:25:28	5872311	804982	0	3	5:25:29	146735	145764	971	0	0
5:25:43	5751209	925882	0	10	5:25:44	146735	145758	977	0	0
5:25:58	5649050	1025192	0	26	5:25:59	146735	145754	981	0	0
5:26:13	5542191	1129502	0	32	5:26:14	146735	145765	970	0	0
5:26:28	5567476	1098431	0	15	5:26:29	146735	145725	1010	0	0
5:26:43	5600712	1065064	0	7	5:26:44	146735	145720	1015	0	0
5:26:58	5624397	1041331	0	1	5:26:59	146735	145715	1020	0	0
5:27:13	5678175	987526	0	0	5:27:14	146735	145725	1010	0	0
5:27:28	5801846	863766	0	4	5:27:29	146735	145725	1010	0	0
5:27:43	5909041	756520	0	1	5:27:44	146735	145714	1021	0	0
5:27:58	6115877	549614	0	3	5:27:59	146735	145754	981	0	0
5:28:13	6225719	439712	0	2	5:28:14	146735	145764	971	0	0
5:28:28	6306554	358773	0	3	5:28:29	146735	145764	971	0	0
5:28:43	6479979	182769	0	0	5:28:44	146735	145759	976	0	0
5:28:58	6477155	185558	0	1	5:28:59	146735	145754	981	0	0
5:29:13	6483916	176334	0	0	5:29:14	146735	145764	971	0	0
5:29:28	6484490	175608	0	8	5:29:29	146735	145764	971	0	0
5:29:43	6479247	180769	0	4	5:29:44	146735	145754	981	0	0
5:29:58	6619282	40561	0	5	5:29:59	146607	145758	849	0	0
5:30:13	6750035	8682	6080	27	5:30:14	146287	145769	518	0	0
5:30:28	6883368	16921	9145	305	5:30:29	146287	145783	504	0	0
5:30:43	6883675	26659	1094	472	5:30:44	146287	145773	514	0	0
5:30:58	6998652	11274	6478	60	5:30:59	146287	145764	523	0	0
5:31:13	7086547	27384	7072	215	5:31:14	146287	145723	564	0	0
5:31:28	7102757	15740	573	254	5:31:29	146287	145733	554	0	0
5:31:43	7102780	13617	416	434	5:31:44	146287	145733	554	0	0
5:31:58	7100241	15577	135	162	5:31:59	146287	145722	565	0	0
5:32:13	7094751	18266	0	154	5:32:14	146287	145717	570	0	0
5:32:28	7054339	13354	1652	194	5:32:29	146287	145711	576	0	0
5:32:43	7166779	12982	5758	286	5:32:44	146287	145713	574	0	0
5:32:58	7159540	13688	2368	1255	5:32:59	146287	145698	589	0	0
5:33:13	7160757	13392	1452	1409	5:33:14	146287	145703	584	0	0
5:33:28	7063973	13343	792	1298	5:33:29	146287	145718	569	0	0
5:33:43	7091761	23755	0	992	5:33:44	146287	145713	574	0	0
5:33:58	7124021	19774	263	939	5:33:59	146287	145713	574	0	0
5:34:13	7157841	13599	4143	719	5:34:14	146287	145712	575	0	0
5:34:28	7193086	131661	1619	1079	5:34:29	146287	145728	559	0	0
5:34:43	7194450	110482	0	1158	5:34:44	146287	145722	565	0	0
5:34:58	7223337	61679	0	1268	5:34:59	146287	145712	575	0	0
5:35:13	7257609	16065	367	1148	5:35:14	146287	145734	553	0	0
5:35:28	7294603	21833	3754	919	5:35:29	146287	145723	564	0	0
5:35:43	7328123	18004	2742	855	5:35:44	146287	145723	564	0	0
5:35:58	7433631	16793	7636	1177	5:35:59	146287	145708	579	0	0
5:36:13	7311956	122769	577	1635	5:36:14	146287	145708	579	0	0
5:36:28	7298350	121975	0	616	5:36:29	146287	145678	609	0	0
5:36:43	7200397	211287	0	551	5:36:44	146287	145679	608	0	0
5:36:58	7211599	195574	0	288	5:36:59	146287	145674	613	0	0
5:37:13	7191540	211208	0	282	5:37:14	146287	145669	618	0	0
5:37:28	7178180	218436	0	403	5:37:29	146287	145680	607	0	0
5:37:43	7199237	193189	0	276	5:37:44	146287	145680	607	0	0
5:37:58	7236189	153162	0	202	5:37:59	146287	145667	620	0	0
5:38:13	7231388	152766	0	338	5:38:14	146287	145678	609	0	0
5:38:28	7246503	131784	0	379	5:38:29	146287	145683	604	0	0
5:38:43	7332105	43150	0	196	5:38:44	146287	145683	604	0	0
5:38:58	7372058	9506	380	69	5:38:59	146287	145692	595	0	0
5:39:13	7440512	17999	5099	302	5:39:14	146287	145672	615	0	0
5:39:28	7359622	120679	1398	68	5:39:29	146287	145683	604	0	0
5:39:43	7339478	138587	0	142	5:39:44	146287	145683	604	0	0
5:39:58	7363002	106450	0	543	5:39:59	146287	145678	609	0	0
5:40:13	7486826	17715	2697	439	5:40:14	146287	145683	604	0	0
5:40:28	7533916	13249	3020	389	5:40:29	146287	145694	593	0	0
5:40:43	7149365	378542	309	413	5:40:44	146287	145699	588	0	0
5:40:58	6856467	651238	0	233	5:40:59	146287	145689	598	0	0