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/slowlink/real/27000e82-c5c4-11df-a7c5-00163e3d3b7c.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/27000e82-c5c4-11df-a7c5-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/real/27000e82-c5c4-11df-a7c5-00163e3d3b7c.cudf.result -sum(changed,installedsize),-count(removed),-notuptodate(solution),-count(changed) 

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.03 1.02 1.00 2/64 20894
/proc/meminfo: memFree=404816/1022884 swapFree=0/0
[pid=20894] ppid=20893 vsize=3152 CPUtime=0
/proc/20894/stat : 20894 (runsolver) R 20893 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120617514 3227648 32 18446744073709551615 134512640 134586868 4287708080 4287706128 4151612464 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/20894/statm: 788 32 0 19 0 73 0

[startup+0.15332 s]
/proc/loadavg: 1.03 1.02 1.00 2/64 20894
/proc/meminfo: memFree=404816/1022884 swapFree=0/0
[pid=20894] ppid=20893 vsize=9212 CPUtime=0.02
/proc/20894/stat : 20894 (aspuncud-full) S 20893 20894 1745 0 -1 4202496 693 2813 0 0 0 0 2 0 20 0 1 0 120617514 9433088 364 18446744073709551615 4194304 5129932 140736217132464 140736217131120 140166854235230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20894/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200272 s]
/proc/loadavg: 1.03 1.02 1.00 2/64 20894
/proc/meminfo: memFree=404816/1022884 swapFree=0/0
[pid=20894] ppid=20893 vsize=9212 CPUtime=0.02
/proc/20894/stat : 20894 (aspuncud-full) S 20893 20894 1745 0 -1 4202496 693 2813 0 0 0 0 2 0 20 0 1 0 120617514 9433088 364 18446744073709551615 4194304 5129932 140736217132464 140736217131120 140166854235230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20894/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300259 s]
/proc/loadavg: 1.03 1.02 1.00 2/64 20894
/proc/meminfo: memFree=404816/1022884 swapFree=0/0
[pid=20894] ppid=20893 vsize=9212 CPUtime=0.02
/proc/20894/stat : 20894 (aspuncud-full) S 20893 20894 1745 0 -1 4202496 693 2813 0 0 0 0 2 0 20 0 1 0 120617514 9433088 364 18446744073709551615 4194304 5129932 140736217132464 140736217131120 140166854235230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20894/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.70022 s]
/proc/loadavg: 1.03 1.02 1.00 2/64 20894
/proc/meminfo: memFree=404816/1022884 swapFree=0/0
[pid=20894] ppid=20893 vsize=9212 CPUtime=0.02
/proc/20894/stat : 20894 (aspuncud-full) S 20893 20894 1745 0 -1 4202496 693 2813 0 0 0 0 2 0 20 0 1 0 120617514 9433088 364 18446744073709551615 4194304 5129932 140736217132464 140736217131120 140166854235230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20894/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50027 s]
/proc/loadavg: 1.03 1.02 1.00 2/66 20907
/proc/meminfo: memFree=344652/1022884 swapFree=0/0
[pid=20894] ppid=20893 vsize=9212 CPUtime=0.02
/proc/20894/stat : 20894 (aspuncud-full) S 20893 20894 1745 0 -1 4202496 693 2813 0 0 0 0 2 0 20 0 1 0 120617514 9433088 364 18446744073709551615 4194304 5129932 140736217132464 140736217131120 140166854235230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20894/statm: 2303 364 303 229 0 63 0
[pid=20907] ppid=20894 vsize=53208 CPUtime=1.38
/proc/20907/stat : 20907 (cudf2lp) R 20894 20894 1745 0 -1 4202496 15643 0 0 0 135 3 0 0 20 0 1 0 120617516 54484992 12245 18446744073709551615 4194304 5690517 140734082651744 140734082649384 4360716 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/20907/statm: 13302 12245 160 366 0 12933 0
Current children cumulated CPU time (s) 1.4
Current children cumulated vsize (KiB) 62420

[startup+3.1002 s]
/proc/loadavg: 1.03 1.02 1.00 2/66 20907
/proc/meminfo: memFree=336096/1022884 swapFree=0/0
[pid=20894] ppid=20893 vsize=9212 CPUtime=2.12
/proc/20894/stat : 20894 (aspuncud-full) S 20893 20894 1745 0 -1 4202496 720 28258 0 0 0 0 202 10 20 0 1 0 120617514 9433088 364 18446744073709551615 4194304 5129932 140736217132464 140736217131120 140166854235230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20894/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.12
Current children cumulated vsize (KiB) 9212
heavy processes:

[startup+6.30028 s]
/proc/loadavg: 1.03 1.02 1.00 2/66 20908
/proc/meminfo: memFree=108680/1022884 swapFree=0/0
[pid=20894] ppid=20893 vsize=9212 CPUtime=2.12
/proc/20894/stat : 20894 (aspuncud-full) S 20893 20894 1745 0 -1 4202496 720 28258 0 0 0 0 202 10 20 0 1 0 120617514 9433088 364 18446744073709551615 4194304 5129932 140736217132464 140736217131120 140166854235230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20894/statm: 2303 364 303 229 0 63 0
[pid=20908] ppid=20894 vsize=408952 CPUtime=4.03
/proc/20908/stat : 20908 (gringo) R 20894 20894 1745 0 -1 4202496 95605 0 0 0 374 29 0 0 20 0 1 0 120617736 418766848 86839 18446744073709551615 4194304 6531320 140736475550640 140736475547256 4331582 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20908/statm: 102238 86839 283 571 0 101659 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 418164

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

[startup+6.40033 s]
/proc/loadavg: 1.03 1.02 1.00 2/66 20908
/proc/meminfo: memFree=108680/1022884 swapFree=0/0
[pid=20894] ppid=20893 vsize=9212 CPUtime=2.12
/proc/20894/stat : 20894 (aspuncud-full) S 20893 20894 1745 0 -1 4202496 720 28258 0 0 0 0 202 10 20 0 1 0 120617514 9433088 364 18446744073709551615 4194304 5129932 140736217132464 140736217131120 140166854235230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20894/statm: 2303 364 303 229 0 63 0
[pid=20908] ppid=20894 vsize=417712 CPUtime=4.13
/proc/20908/stat : 20908 (gringo) R 20894 20894 1745 0 -1 4202496 97501 0 0 0 383 30 0 0 20 0 1 0 120617736 427737088 88735 18446744073709551615 4194304 6531320 140736475550640 140736475547256 4360971 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20908/statm: 104428 88735 283 571 0 103849 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 426924

[startup+7.20029 s]
/proc/loadavg: 1.03 1.02 1.00 2/66 20908
/proc/meminfo: memFree=9316/1022884 swapFree=0/0
[pid=20894] ppid=20893 vsize=9212 CPUtime=2.12
/proc/20894/stat : 20894 (aspuncud-full) S 20893 20894 1745 0 -1 4202496 720 28258 0 0 0 0 202 10 20 0 1 0 120617514 9433088 364 18446744073709551615 4194304 5129932 140736217132464 140736217131120 140166854235230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20894/statm: 2303 364 303 229 0 63 0
[pid=20908] ppid=20894 vsize=432552 CPUtime=4.84
/proc/20908/stat : 20908 (gringo) R 20894 20894 1745 0 -1 4202496 109075 0 0 0 449 35 0 0 20 0 1 0 120617736 442933248 92276 18446744073709551615 4194304 6531320 140736475550640 140736475548328 5507373 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20908/statm: 108138 92276 284 571 0 107559 0
Current children cumulated CPU time (s) 6.96
Current children cumulated vsize (KiB) 441764

[startup+8.00037 s]
/proc/loadavg: 1.03 1.02 1.00 2/67 20910
/proc/meminfo: memFree=315132/1022884 swapFree=0/0
[pid=20894] ppid=20893 vsize=9212 CPUtime=7.18
/proc/20894/stat : 20894 (aspuncud-full) S 20893 20894 1745 0 -1 4202496 759 137337 0 0 0 0 664 54 20 0 1 0 120617514 9433088 364 18446744073709551615 4194304 5129932 140736217132464 140736217130528 140166854235230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20894/statm: 2303 364 303 229 0 63 0
[pid=20909] ppid=20894 vsize=143444 CPUtime=0.57
/proc/20909/stat : 20909 (unclasp) R 20894 20894 1745 0 -1 4202496 39414 0 1 0 53 4 0 0 20 0 1 0 120618254 146886656 35233 18446744073709551615 4194304 6012874 140736884306272 140736884304760 4633582 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/20909/statm: 35861 35233 187 444 0 35409 0
[pid=20910] ppid=20894 vsize=22040 CPUtime=0.01
/proc/20910/stat : 20910 (parse.py) S 20894 20894 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120618254 22568960 1128 18446744073709551615 4194304 6642060 140734973931328 140734973929688 140357156820768 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20910/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 7.76
Current children cumulated vsize (KiB) 174696

[startup+8.40034 s]
/proc/loadavg: 1.03 1.02 1.00 2/67 20910
/proc/meminfo: memFree=315132/1022884 swapFree=0/0
[pid=20894] ppid=20893 vsize=9212 CPUtime=7.18
/proc/20894/stat : 20894 (aspuncud-full) S 20893 20894 1745 0 -1 4202496 759 137337 0 0 0 0 664 54 20 0 1 0 120617514 9433088 364 18446744073709551615 4194304 5129932 140736217132464 140736217130528 140166854235230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20894/statm: 2303 364 303 229 0 63 0
[pid=20909] ppid=20894 vsize=139280 CPUtime=0.96
/proc/20909/stat : 20909 (unclasp) R 20894 20894 1745 0 -1 4202496 40485 0 1 0 92 4 0 0 20 0 1 0 120618254 142622720 34306 18446744073709551615 4194304 6012874 140736884306272 140736884305336 4539427 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/20909/statm: 34820 34306 225 444 0 34368 0
[pid=20910] ppid=20894 vsize=22380 CPUtime=0.01
/proc/20910/stat : 20910 (parse.py) S 20894 20894 1745 0 -1 4202496 1374 0 0 0 1 0 0 0 20 0 1 0 120618254 22917120 1184 18446744073709551615 4194304 6642060 140734973931328 140734973929336 140357156820768 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20910/statm: 5595 1184 508 598 0 681 0
Current children cumulated CPU time (s) 8.15
Current children cumulated vsize (KiB) 170872

Child status: 0
Real time (s): 8.48239
CPU time (s): 8.26451
CPU user time (s): 7.61248
CPU system time (s): 0.65204
CPU usage (%): 97.4315
Max. virtual memory (cumulated for all children) (KiB): 476588

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.61247
system time used= 0.65204
maximum resident set size= 401236
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 180287
page faults= 1
swaps= 0
block input operations= 43968
block output operations= 46952
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 165
involuntary context switches= 1104

runsolver used 0.024001 second user time and 0.028001 second system time

The end