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 300 -d 10 -w /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/real/2c3aece6-c8b2-11df-a040-00163e3d3b7c.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/2c3aece6-c8b2-11df-a040-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/real/2c3aece6-c8b2-11df-a040-00163e3d3b7c.cudf.result -count(removed),-sum(solution,installedsize),-notuptodate(solution),-unsat_recommends(solution),-count(new) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 330 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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.02 1.01 0.94 2/64 17446
/proc/meminfo: memFree=651080/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9204 CPUtime=0
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 119683199 9424896 332 18446744073709551615 4194304 5129932 140734972894064 140734972891528 139777981966112 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2301 332 272 229 0 61 0

[startup+0.201258 s]
/proc/loadavg: 1.02 1.01 0.94 2/64 17446
/proc/meminfo: memFree=651080/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=0.02
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 697 2810 0 0 0 0 1 1 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892720 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300345 s]
/proc/loadavg: 1.02 1.01 0.94 2/64 17446
/proc/meminfo: memFree=651080/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=0.02
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 697 2810 0 0 0 0 1 1 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892720 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.400329 s]
/proc/loadavg: 1.02 1.01 0.94 2/64 17446
/proc/meminfo: memFree=651080/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=0.02
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 697 2810 0 0 0 0 1 1 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892720 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700223 s]
/proc/loadavg: 1.02 1.01 0.94 2/64 17446
/proc/meminfo: memFree=651080/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=0.02
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 697 2810 0 0 0 0 1 1 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892720 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 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.02 1.01 0.94 2/66 17459
/proc/meminfo: memFree=612864/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=0.02
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 697 2810 0 0 0 0 1 1 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892720 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 303 229 0 63 0
[pid=17459] ppid=17446 vsize=52872 CPUtime=1.43
/proc/17459/stat : 17459 (cudf2lp) R 17446 17446 1745 0 -1 4202496 14685 0 0 0 137 6 0 0 20 0 1 0 119683202 54140928 11287 18446744073709551615 4194304 5690517 140733656235872 140733656233240 4293334 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/17459/statm: 13218 11287 160 366 0 12849 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 62084

[startup+3.10032 s]
/proc/loadavg: 1.02 1.01 0.94 2/66 17459
/proc/meminfo: memFree=560908/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=2.98
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 724 26781 0 0 0 0 281 17 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892720 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 2.98
Current children cumulated vsize (KiB) 9212

[startup+6.30031 s]
/proc/loadavg: 1.02 1.01 0.94 2/66 17460
/proc/meminfo: memFree=518252/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=2.98
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 724 26781 0 0 0 0 281 17 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892720 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 303 229 0 63 0
[pid=17460] ppid=17446 vsize=148672 CPUtime=3.22
/proc/17460/stat : 17460 (gringo) R 17446 17446 1745 0 -1 4202496 35920 0 0 0 302 20 0 0 20 0 1 0 119683503 152240128 31735 18446744073709551615 4194304 6531320 140734808519952 140734808516936 4359010 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17460/statm: 37168 31735 281 571 0 36589 0
Current children cumulated CPU time (s) 6.2
Current children cumulated vsize (KiB) 157884

[startup+12.7003 s]
/proc/loadavg: 1.02 1.01 0.94 2/67 17462
/proc/meminfo: memFree=485632/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=9.9
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 763 122087 0 0 0 0 913 77 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892128 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 303 229 0 63 0
[pid=17461] ppid=17446 vsize=122704 CPUtime=2.62
/proc/17461/stat : 17461 (unclasp) R 17446 17446 1745 0 -1 4202496 35998 0 0 0 248 14 0 0 20 0 1 0 119684202 125648896 30057 18446744073709551615 4194304 6012874 140736469820576 140736469819896 4299990 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17461/statm: 30676 30057 226 444 0 30224 0
[pid=17462] ppid=17446 vsize=22188 CPUtime=0.02
/proc/17462/stat : 17462 (parse.py) S 17446 17446 1745 0 -1 4202496 1341 0 0 0 1 1 0 0 20 0 1 0 119684202 22720512 1151 18446744073709551615 4194304 6642060 140733864194336 140733864192216 140731937609504 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17462/statm: 5547 1151 508 598 0 633 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 154104

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

[startup+12.9004 s]
/proc/loadavg: 1.02 1.01 0.94 2/67 17462
/proc/meminfo: memFree=485632/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=9.9
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 763 122087 0 0 0 0 913 77 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892128 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 303 229 0 63 0
[pid=17461] ppid=17446 vsize=122704 CPUtime=2.81
/proc/17461/stat : 17461 (unclasp) R 17446 17446 1745 0 -1 4202496 35998 0 0 0 267 14 0 0 20 0 1 0 119684202 125648896 30057 18446744073709551615 4194304 6012874 140736469820576 140736469819896 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17461/statm: 30676 30057 226 444 0 30224 0
[pid=17462] ppid=17446 vsize=22188 CPUtime=0.02
/proc/17462/stat : 17462 (parse.py) S 17446 17446 1745 0 -1 4202496 1341 0 0 0 1 1 0 0 20 0 1 0 119684202 22720512 1151 18446744073709551615 4194304 6642060 140733864194336 140733864192216 140731937609504 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17462/statm: 5547 1151 508 598 0 633 0
Current children cumulated CPU time (s) 12.73
Current children cumulated vsize (KiB) 154104

[startup+14.5044 s]
/proc/loadavg: 1.02 1.01 0.94 2/67 17462
/proc/meminfo: memFree=485756/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=9.9
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 763 122087 0 0 0 0 913 77 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892128 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 303 229 0 63 0
[pid=17461] ppid=17446 vsize=122704 CPUtime=4.4
/proc/17461/stat : 17461 (unclasp) R 17446 17446 1745 0 -1 4202496 35998 0 0 0 426 14 0 0 20 0 1 0 119684202 125648896 30057 18446744073709551615 4194304 6012874 140736469820576 140736469819896 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17461/statm: 30676 30057 226 444 0 30224 0
[pid=17462] ppid=17446 vsize=22360 CPUtime=0.02
/proc/17462/stat : 17462 (parse.py) S 17446 17446 1745 0 -1 4202496 1395 0 0 0 1 1 0 0 20 0 1 0 119684202 22896640 1205 18446744073709551615 4194304 6642060 140733864194336 140733864192376 140731937609504 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17462/statm: 5590 1205 508 598 0 676 0
Current children cumulated CPU time (s) 14.32
Current children cumulated vsize (KiB) 154276

[startup+15.3004 s]
/proc/loadavg: 1.02 1.01 0.94 2/67 17462
/proc/meminfo: memFree=485756/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=9.9
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 763 122087 0 0 0 0 913 77 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892128 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 303 229 0 63 0
[pid=17461] ppid=17446 vsize=122704 CPUtime=5.19
/proc/17461/stat : 17461 (unclasp) R 17446 17446 1745 0 -1 4202496 35998 0 0 0 504 15 0 0 20 0 1 0 119684202 125648896 30057 18446744073709551615 4194304 6012874 140736469820576 140736469819896 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17461/statm: 30676 30057 226 444 0 30224 0
[pid=17462] ppid=17446 vsize=22360 CPUtime=0.02
/proc/17462/stat : 17462 (parse.py) S 17446 17446 1745 0 -1 4202496 1395 0 0 0 1 1 0 0 20 0 1 0 119684202 22896640 1205 18446744073709551615 4194304 6642060 140733864194336 140733864192376 140731937609504 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17462/statm: 5590 1205 508 598 0 676 0
Current children cumulated CPU time (s) 15.11
Current children cumulated vsize (KiB) 154276

[startup+15.7004 s]
/proc/loadavg: 1.01 1.01 0.94 2/67 17462
/proc/meminfo: memFree=485756/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=9.9
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 763 122087 0 0 0 0 913 77 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892128 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 303 229 0 63 0
[pid=17461] ppid=17446 vsize=122704 CPUtime=5.59
/proc/17461/stat : 17461 (unclasp) R 17446 17446 1745 0 -1 4202496 35998 0 0 0 544 15 0 0 20 0 1 0 119684202 125648896 30057 18446744073709551615 4194304 6012874 140736469820576 140736469819896 4525916 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17461/statm: 30676 30057 226 444 0 30224 0
[pid=17462] ppid=17446 vsize=22360 CPUtime=0.02
/proc/17462/stat : 17462 (parse.py) S 17446 17446 1745 0 -1 4202496 1395 0 0 0 1 1 0 0 20 0 1 0 119684202 22896640 1205 18446744073709551615 4194304 6642060 140733864194336 140733864192376 140731937609504 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17462/statm: 5590 1205 508 598 0 676 0
Current children cumulated CPU time (s) 15.51
Current children cumulated vsize (KiB) 154276

[startup+16.1008 s]
/proc/loadavg: 1.01 1.01 0.94 2/67 17462
/proc/meminfo: memFree=485756/1022884 swapFree=0/0
[pid=17446] ppid=17445 vsize=9212 CPUtime=9.9
/proc/17446/stat : 17446 (aspuncud-full) S 17445 17446 1745 0 -1 4202496 763 122087 0 0 0 0 913 77 20 0 1 0 119683199 9433088 365 18446744073709551615 4194304 5129932 140734972894064 140734972892128 139777981822046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17446/statm: 2303 365 303 229 0 63 0
[pid=17461] ppid=17446 vsize=122704 CPUtime=5.98
/proc/17461/stat : 17461 (unclasp) R 17446 17446 1745 0 -1 4202496 36006 0 0 0 580 18 0 0 20 0 1 0 119684202 125648896 369 18446744073709551615 4194304 6012874 140736469820576 140736469819976 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17461/statm: 30676 369 234 444 0 30224 0
[pid=17462] ppid=17446 vsize=22512 CPUtime=0.02
/proc/17462/stat : 17462 (parse.py) S 17446 17446 1745 0 -1 4202496 1408 0 0 0 1 1 0 0 20 0 1 0 119684202 23052288 1218 18446744073709551615 4194304 6642060 140733864194336 140733864192296 140731937609504 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17462/statm: 5628 1218 508 598 0 714 0
Current children cumulated CPU time (s) 15.9
Current children cumulated vsize (KiB) 154428

Child status: 0
Real time (s): 16.1168
CPU time (s): 15.949
CPU user time (s): 14.9689
CPU system time (s): 0.980061
CPU usage (%): 98.9589
Max. virtual memory (cumulated for all children) (KiB): 422456

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 14.9689
system time used= 0.980061
maximum resident set size= 348080
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 160550
page faults= 0
swaps= 0
block input operations= 40776
block output operations= 43656
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 201
involuntary context switches= 2009

runsolver used 0.040002 second user time and 0.076004 second system time

The end