runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

command line: runsolver -s SIGUSR1 -M 1124 -C 150 -d 10 -w /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/paranoid-size/install/rand118.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/install/rand118.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/paranoid-size/install/rand118.cudf.result -count(removed),-sum(solution,installedsize),-count(changed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 150 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 180 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB

[startup+0 s]
/proc/loadavg: 1.08 1.02 0.91 2/60 21439
/proc/meminfo: memFree=454292/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=3152 CPUtime=0
/proc/21439/stat : 21439 (runsolver) R 21438 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115370839 3227648 33 18446744073709551615 134512640 134586868 4290942352 4290940400 4151383088 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.157465 s]
/proc/loadavg: 1.08 1.02 0.91 2/60 21439
/proc/meminfo: memFree=454292/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=0.02
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 695 2807 0 0 0 0 2 0 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694624 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200285 s]
/proc/loadavg: 1.08 1.02 0.91 2/60 21439
/proc/meminfo: memFree=454292/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=0.02
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 695 2807 0 0 0 0 2 0 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694624 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300279 s]
/proc/loadavg: 1.08 1.02 0.91 2/60 21439
/proc/meminfo: memFree=454292/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=0.02
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 695 2807 0 0 0 0 2 0 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694624 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700319 s]
/proc/loadavg: 1.08 1.02 0.91 2/60 21439
/proc/meminfo: memFree=454292/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=0.02
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 695 2807 0 0 0 0 2 0 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694624 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 1.08 1.02 0.91 2/62 21452
/proc/meminfo: memFree=434924/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=0.02
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 695 2807 0 0 0 0 2 0 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694624 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
[pid=21452] ppid=21439 vsize=27708 CPUtime=0.78
/proc/21452/stat : 21452 (cudf2lp) R 21439 21439 1733 0 -1 4202496 7787 0 0 0 74 4 0 0 20 0 1 0 115370841 28372992 6054 18446744073709551615 4194304 5690517 140736241321920 140736241319560 4680480 0 0 16781316 0 0 0 0 17 0 0 0 68 0 0
/proc/21452/statm: 6927 6054 159 366 0 6558 0
Current children cumulated CPU time (s) 0.8
Current children cumulated vsize (KiB) 36920

[startup+3.10034 s]
/proc/loadavg: 1.08 1.02 0.91 2/62 21452
/proc/meminfo: memFree=396236/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=0.02
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 695 2807 0 0 0 0 2 0 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694624 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
[pid=21452] ppid=21439 vsize=52128 CPUtime=2.36
/proc/21452/stat : 21452 (cudf2lp) R 21439 21439 1733 0 -1 4202496 15833 0 0 0 227 9 0 0 20 0 1 0 115370841 53379072 12435 18446744073709551615 4194304 5690517 140736241321920 140736241319560 4249585 0 0 16781316 0 0 0 0 17 0 0 0 68 0 0
/proc/21452/statm: 13032 12435 160 366 0 12663 0
Current children cumulated CPU time (s) 2.38
Current children cumulated vsize (KiB) 61340
heavy processes:

[startup+6.30023 s]
/proc/loadavg: 1.07 1.02 0.91 2/62 21452
/proc/meminfo: memFree=296044/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=4.89
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 723 42127 0 0 0 0 464 25 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694624 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 4.89
Current children cumulated vsize (KiB) 9212
heavy processes:

[startup+12.7005 s]
/proc/loadavg: 1.07 1.02 0.91 2/62 21453
/proc/meminfo: memFree=10072/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=4.89
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 723 42127 0 0 0 0 464 25 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694624 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
[pid=21453] ppid=21439 vsize=387580 CPUtime=6.93
/proc/21453/stat : 21453 (gringo) R 21439 21439 1733 0 -1 4202496 109896 0 0 0 644 49 0 0 20 0 1 0 115371404 396881920 56945 18446744073709551615 4194304 6531320 140735979503200 140735979500824 5808234 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21453/statm: 96895 56945 284 571 0 96316 0
Current children cumulated CPU time (s) 11.82
Current children cumulated vsize (KiB) 396792

[startup+25.5004 s]
/proc/loadavg: 1.05 1.01 0.91 2/63 21455
/proc/meminfo: memFree=273836/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=11.89
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 765 152027 0 0 0 0 1109 80 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694032 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
[pid=21454] ppid=21439 vsize=137732 CPUtime=12.58
/proc/21454/stat : 21454 (unclasp) R 21439 21439 1733 0 -1 4202496 40008 0 1 0 1243 15 0 0 20 0 1 0 115372115 141037568 33874 18446744073709551615 4194304 6012874 140736055838320 140736055837640 4548906 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/21454/statm: 34433 33874 230 444 0 33981 0
[pid=21455] ppid=21439 vsize=22336 CPUtime=0.01
/proc/21455/stat : 21455 (parse.py) S 21439 21439 1733 0 -1 4202496 1363 0 0 0 1 0 0 0 20 0 1 0 115372115 22872064 1173 18446744073709551615 4194304 6642060 140734864928864 140734864927144 140468558702368 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21455/statm: 5584 1173 508 598 0 670 0
Current children cumulated CPU time (s) 24.48
Current children cumulated vsize (KiB) 169280

Solver just ended. Dumping a history of the last processes samples

[startup+25.6006 s]
/proc/loadavg: 1.05 1.01 0.91 2/63 21455
/proc/meminfo: memFree=273836/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=11.89
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 765 152027 0 0 0 0 1109 80 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694032 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
[pid=21454] ppid=21439 vsize=137732 CPUtime=12.68
/proc/21454/stat : 21454 (unclasp) R 21439 21439 1733 0 -1 4202496 40008 0 1 0 1253 15 0 0 20 0 1 0 115372115 141037568 33874 18446744073709551615 4194304 6012874 140736055838320 140736055837640 4548906 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/21454/statm: 34433 33874 230 444 0 33981 0
[pid=21455] ppid=21439 vsize=22336 CPUtime=0.01
/proc/21455/stat : 21455 (parse.py) S 21439 21439 1733 0 -1 4202496 1363 0 0 0 1 0 0 0 20 0 1 0 115372115 22872064 1173 18446744073709551615 4194304 6642060 140734864928864 140734864927144 140468558702368 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21455/statm: 5584 1173 508 598 0 670 0
Current children cumulated CPU time (s) 24.58
Current children cumulated vsize (KiB) 169280

[startup+27.2004 s]
/proc/loadavg: 1.05 1.01 0.91 2/63 21455
/proc/meminfo: memFree=273836/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=11.89
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 765 152027 0 0 0 0 1109 80 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694032 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
[pid=21454] ppid=21439 vsize=137732 CPUtime=14.27
/proc/21454/stat : 21454 (unclasp) R 21439 21439 1733 0 -1 4202496 40008 0 1 0 1411 16 0 0 20 0 1 0 115372115 141037568 33874 18446744073709551615 4194304 6012874 140736055838320 140736055837640 4548431 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/21454/statm: 34433 33874 230 444 0 33981 0
[pid=21455] ppid=21439 vsize=22336 CPUtime=0.01
/proc/21455/stat : 21455 (parse.py) S 21439 21439 1733 0 -1 4202496 1363 0 0 0 1 0 0 0 20 0 1 0 115372115 22872064 1173 18446744073709551615 4194304 6642060 140734864928864 140734864927144 140468558702368 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21455/statm: 5584 1173 508 598 0 670 0
Current children cumulated CPU time (s) 26.17
Current children cumulated vsize (KiB) 169280

[startup+28.8004 s]
/proc/loadavg: 1.05 1.01 0.91 2/63 21455
/proc/meminfo: memFree=273836/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=11.89
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 765 152027 0 0 0 0 1109 80 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694032 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
[pid=21454] ppid=21439 vsize=137732 CPUtime=15.84
/proc/21454/stat : 21454 (unclasp) R 21439 21439 1733 0 -1 4202496 40009 0 1 0 1568 16 0 0 20 0 1 0 115372115 141037568 33875 18446744073709551615 4194304 6012874 140736055838320 140736055837640 4525916 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/21454/statm: 34433 33875 230 444 0 33981 0
[pid=21455] ppid=21439 vsize=22336 CPUtime=0.01
/proc/21455/stat : 21455 (parse.py) S 21439 21439 1733 0 -1 4202496 1363 0 0 0 1 0 0 0 20 0 1 0 115372115 22872064 1173 18446744073709551615 4194304 6642060 140734864928864 140734864927144 140468558702368 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21455/statm: 5584 1173 508 598 0 670 0
Current children cumulated CPU time (s) 27.74
Current children cumulated vsize (KiB) 169280

[startup+29.6004 s]
/proc/loadavg: 1.05 1.01 0.91 2/63 21455
/proc/meminfo: memFree=273836/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=11.89
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 765 152027 0 0 0 0 1109 80 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694032 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
[pid=21454] ppid=21439 vsize=137732 CPUtime=16.64
/proc/21454/stat : 21454 (unclasp) R 21439 21439 1733 0 -1 4202496 40009 0 1 0 1648 16 0 0 20 0 1 0 115372115 141037568 33875 18446744073709551615 4194304 6012874 140736055838320 140736055837640 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/21454/statm: 34433 33875 230 444 0 33981 0
[pid=21455] ppid=21439 vsize=22336 CPUtime=0.01
/proc/21455/stat : 21455 (parse.py) S 21439 21439 1733 0 -1 4202496 1363 0 0 0 1 0 0 0 20 0 1 0 115372115 22872064 1173 18446744073709551615 4194304 6642060 140734864928864 140734864927144 140468558702368 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21455/statm: 5584 1173 508 598 0 670 0
Current children cumulated CPU time (s) 28.54
Current children cumulated vsize (KiB) 169280

[startup+29.805 s]
/proc/loadavg: 1.05 1.01 0.91 2/63 21455
/proc/meminfo: memFree=273836/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=11.89
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 765 152027 0 0 0 0 1109 80 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694032 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
[pid=21454] ppid=21439 vsize=137732 CPUtime=16.84
/proc/21454/stat : 21454 (unclasp) R 21439 21439 1733 0 -1 4202496 40009 0 1 0 1668 16 0 0 20 0 1 0 115372115 141037568 33875 18446744073709551615 4194304 6012874 140736055838320 140736055837640 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/21454/statm: 34433 33875 230 444 0 33981 0
[pid=21455] ppid=21439 vsize=22336 CPUtime=0.01
/proc/21455/stat : 21455 (parse.py) S 21439 21439 1733 0 -1 4202496 1363 0 0 0 1 0 0 0 20 0 1 0 115372115 22872064 1173 18446744073709551615 4194304 6642060 140734864928864 140734864927144 140468558702368 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21455/statm: 5584 1173 508 598 0 670 0
Current children cumulated CPU time (s) 28.74
Current children cumulated vsize (KiB) 169280

[startup+29.9013 s]
/proc/loadavg: 1.05 1.01 0.91 2/63 21455
/proc/meminfo: memFree=273836/1022884 swapFree=0/0
[pid=21439] ppid=21438 vsize=9212 CPUtime=11.89
/proc/21439/stat : 21439 (aspuncud-basic) S 21438 21439 1733 0 -1 4202496 765 152027 0 0 0 0 1109 80 20 0 1 0 115370839 9433088 364 18446744073709551615 4194304 5129932 140736847695968 140736847694032 140040593679454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21439/statm: 2303 364 303 229 0 63 0
[pid=21454] ppid=21439 vsize=137732 CPUtime=16.93
/proc/21454/stat : 21454 (unclasp) R 21439 21439 1733 0 -1 4202496 40016 0 1 0 1677 16 0 0 20 0 1 0 115372115 141037568 29786 18446744073709551615 4194304 6012874 140736055838320 140736055837720 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/21454/statm: 34433 29786 237 444 0 33981 0
[pid=21455] ppid=21439 vsize=22336 CPUtime=0.01
/proc/21455/stat : 21455 (parse.py) S 21439 21439 1733 0 -1 4202496 1363 0 0 0 1 0 0 0 20 0 1 0 115372115 22872064 1173 18446744073709551615 4194304 6642060 140734864928864 140734864927064 140468558702368 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21455/statm: 5584 1173 508 598 0 670 0
Current children cumulated CPU time (s) 28.83
Current children cumulated vsize (KiB) 169280

Child status: 0
Real time (s): 29.9652
CPU time (s): 28.9258
CPU user time (s): 27.8897
CPU system time (s): 1.03606
CPU usage (%): 96.5314
Max. virtual memory (cumulated for all children) (KiB): 475756

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 27.8897
system time used= 1.03606
maximum resident set size= 402464
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 194459
page faults= 1
swaps= 0
block input operations= 68520
block output operations= 51064
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 122
involuntary context switches= 3407

runsolver used 0.064004 second user time and 0.16001 second system time

The end