Tuesday, September 09, 2008

Memory Utilisation In Linux, Part 2

Wanna see the symptom of memory shortage ? Here is a Python script to 'swallow' 10MB of memory every second:
#! /usr/bin/python

import time

a=[]
while 1:
        a.append('a'*10*1024*1024)
        time.sleep(1)
While the above script is running in the background, here is the output from sar -r 5 100:
# sar -r 5 100
Linux 2.6.18-8.1.8.el5 (chihung)        09/09/2008

07:14:29 PM kbmemfree kbmemused  %memused kbbuffers  kbcached kbswpfree kbswpused  %swpused  kbswpcad
07:14:34 PM     56396   2019244     97.28    128784   1545336   2031524        84      0.00         0
07:14:39 PM     54876   2020764     97.36    128608   1495564   2031524        84      0.00         0
07:14:44 PM     54704   2020936     97.36    127972   1445768   2031524        84      0.00         0
07:14:49 PM     55540   2020100     97.32    127496   1394408   2031524        84      0.00         0
07:14:54 PM     55600   2020040     97.32    126932   1343752   2031524        84      0.00         0
07:14:59 PM     54452   2021188     97.38    126624   1294228   2031524        84      0.00         0
07:15:04 PM     53116   2022524     97.44    126304   1245076   2031524        84      0.00         0
07:15:09 PM     54484   2021156     97.38    125884   1193316   2031524        84      0.00         0

07:15:09 PM kbmemfree kbmemused  %memused kbbuffers  kbcached kbswpfree kbswpused  %swpused  kbswpcad
07:15:14 PM     52784   2022856     97.46    125300   1144816   2031524        84      0.00         0
07:15:19 PM     54800   2020840     97.36    124684   1092436   2031524        84      0.00         0
07:15:24 PM     54920   2020720     97.35    124200   1052136   2031524        84      0.00         0
07:15:29 PM     51652   2023988     97.51    123724   1004592   2031524        84      0.00         0
07:15:34 PM     52280   2023360     97.48    123368    964236   2031524        84      0.00         0
07:15:39 PM     54624   2021016     97.37    122944    912644   2031524        84      0.00         0
07:15:44 PM     53756   2021884     97.41    122576    874024   2031524        84      0.00         0

07:15:44 PM kbmemfree kbmemused  %memused kbbuffers  kbcached kbswpfree kbswpused  %swpused  kbswpcad
07:15:49 PM     52632   2023008     97.46    122440    825380   2031524        84      0.00         0
07:15:54 PM     53488   2022152     97.42    122288    775016   2031524        84      0.00         0
07:15:59 PM     52632   2023008     97.46    122068    727192   2031524        84      0.00         0
07:16:04 PM     53220   2022420     97.44    121928    678084   2031524        84      0.00         0
07:16:09 PM     54432   2021208     97.38    121792    627572   2031524        84      0.00         0
07:16:14 PM     52196   2023444     97.49    121436    581396   2031524        84      0.00         0
07:16:19 PM     53572   2022068     97.42    121068    531860   2031524        84      0.00         0

07:16:19 PM kbmemfree kbmemused  %memused kbbuffers  kbcached kbswpfree kbswpused  %swpused  kbswpcad
07:16:24 PM     52192   2023448     97.49    120800    485084   2031524        84      0.00         0
07:16:29 PM     51588   2024052     97.51    109316    448756   2031524        84      0.00         0
07:16:34 PM     52528   2023112     97.47    103308    414500   2031524        84      0.00         0
07:16:39 PM     55024   2020616     97.35     96268    369416   2031524        84      0.00         0
07:16:44 PM     54404   2021236     97.38     87060    330008   2031524        84      0.00         0
07:16:49 PM     51752   2023888     97.51     79648    290004   2031524        84      0.00         0
07:16:54 PM     53224   2022416     97.44     68392    250512   2031524        84      0.00         0
07:16:59 PM     54384   2021256     97.38     59184    208384   2031524        84      0.00         0

07:16:59 PM kbmemfree kbmemused  %memused kbbuffers  kbcached kbswpfree kbswpused  %swpused  kbswpcad
07:17:04 PM     55544   2020096     97.32     46008    171400   2031524        84      0.00         0
07:17:09 PM     54532   2021108     97.37     28476    141884   2031396       212      0.01       128
07:17:14 PM     54372   2021268     97.38     12612    120860   2030756       852      0.04       128
07:17:19 PM     52628   2023012     97.46      2252     85396   2030116      1492      0.07       128
07:17:24 PM     51716   2023924     97.51       144     43988   2009848     21760      1.07     16244
07:17:29 PM     60688   2014952     97.08       208     44044   1956132     75476      3.72     14236
07:17:34 PM     54932   2020708     97.35       216     44068   1915068    116540      5.74     12644

07:17:34 PM kbmemfree kbmemused  %memused kbbuffers  kbcached kbswpfree kbswpused  %swpused  kbswpcad
07:17:39 PM     53980   2021660     97.40       216     44160   1878736    152872      7.52      1340
07:17:44 PM     55072   2020568     97.35       212     44208   1823232    208376     10.26     16704
07:17:49 PM     51976   2023664     97.50       220     44276   1779172    252436     12.43     13948
07:17:54 PM     52052   2023588     97.49       228     44176   1734720    296888     14.61      8260
07:17:59 PM     53116   2022524     97.44       236     44104   1671496    360112     17.73     19380
07:18:04 PM     51824   2023816     97.50       268     44012   1628964    402644     19.82     13436
07:18:09 PM     56040   2019600     97.30       276     44396   1557816    473792     23.32     40076

07:18:09 PM kbmemfree kbmemused  %memused kbbuffers  kbcached kbswpfree kbswpused  %swpused  kbswpcad
07:18:14 PM     53260   2022380     97.43       288     44364   1544164    487444     23.99      6492
07:18:19 PM     52592   2023048     97.47       288     42052   1473880    557728     27.45     27956
07:18:24 PM   1878472    197168      9.50       372     40140   1943788     87820      4.32      2520
07:18:29 PM   1878596    197044      9.49       384     40108   1943788     87820      4.32      2520
07:18:34 PM   1878844    196796      9.48       384     40108   1943788     87820      4.32      2520
07:18:39 PM   1878968    196672      9.48       392     40108   1943788     87820      4.32      2520
07:18:44 PM   1878968    196672      9.48       396     40168   1943788     87820      4.32      2520
07:18:49 PM   1878968    196672      9.48       404     40184   1943788     87820      4.32      2520

I terminated the Python script at 07:18:24. As you can see, although the %memused started at 97%, it is until 2.5 minutes later we can see swap kicked in. That is about about 1.5GB of memory allocated to the Python program. During this 2.5 minute, the system will page out whatever not necessary in the memory cache to give memory space to the Python program. That's why you do not see any memory shortage or swapping for the first two and a half minutes. However, when the Python program still keep on 'swallowing' more memory, the system has no more memory cache to page out. At this stage, the system has to resolve to swapping out memory pages to swap partition (that's will be in disk). As you can see, the 'kbswpused' and '%swpused' keep going up and this is a clear indication of memory shortage.

When we terminate our Python program, all memory previously allocated in the heap will be returned back to the system. During the entire run of the Python program, it 'swallowed' almost 1.8GB of memory and that's why you will see the %memused dropped down to less than 10%.

Labels: ,

0 Comments:

Post a Comment

<< Home