Strange Zappa Mexico behavior

[ernst]

Hello,

I've noticed a strange behavior with Zappa Mexico x64 which I cannot explain. Sometimes, during search, the KN/s starts to drop considerably.
Looking through the log, I see a large idle time on one of the CPU's during that search. Next move things are back to normal.

It has nothing to do with TB access (it happens also when there is no TB access), instability or a cpu throttling. System is mildly overclocked (Q6600 @ 3GHz) and Prime95 stable. I have a Scythe cooler on the cpu and the core temps are about 50 degrees centigrade with prime95 running on all 4 cores.

I have never noticed this behavior with other engines like Deep Shredder and Rybka.

I wonder if anyone else ever noticed this or if someone is willing to look through their logs?

Thanks,
Ernst.

Code: Select all

1... Rf8xf6 2. Na3-c2 Nc5-d3 3. Rc4xe4 Rf6-f1 4. Nc2-e1 Nd3xe1 5. Re3xe1 Rf1xe1 6. Re4xe1 Be7xh4 7. Re1-b1 h7-h5 8. b2-b4 Bh4-f2 9. b4-b5 Bf2-b6 10. Rb1-d1 h5-h4 11. Ka1-b2 Bb6-c7 
 = (0.86)	Depth: 18/0	00:00:00.00	0kN (1 KN/s, 0 splits, 0 aborts)
1... Rf8xf6 2. Na3-c2 Nc5-d3 3. Rc4xe4 Rf6-f1 4. Nc2-e1 Nd3xe1 5. Re3xe1 Rf1xe1 6. Re4xe1 Be7xh4 7. Re1-b1 h7-h5 8. b2-b4 Bh4-f2 9. b4-b5 Bf2-b6 10. Rb1-d1 h5-h4 11. Ka1-b2 Bb6-c7 
 = (0.86)	Depth: 18/0	00:00:00.00	0kN (1 KN/s, 0 splits, 0 aborts)
1... Rf8xf6 2. Na3-c2 Nc5-d3 3. Rc4xe4 Rf6-f1 4. Nc2-e1 Nd3xe1 5. Re3xe1 Rf1xe1 6. Re4xe1 Be7xh4 7. Re1-b1 h7-h5 8. b2-b4 Bh4-f2 9. b4-b5 Bf2-b6 10. Rb1-h1 g7-g6 11. Rh1-d1 Kg8-f7 12. Rd1-d6 
 = (0.91)	Depth: 19/47	00:01:01.11	218293kN (3572 KN/s, 64036 splits, 3359 aborts)
1... Rf8xf6 2. Na3-c2 Nc5-d3 3. Rc4xe4 Rf6-f1 4. Nc2-e1 Nd3xe1 5. Re3xe1 Rf1xe1 6. Re4xe1 Be7xh4 7. Re1-b1 h7-h5 8. b2-b4 Bh4-f2 9. b4-b5 Bf2-b6 10. Rb1-h1 g7-g6 11. Rh1-d1 Kg8-f7 12. Rd1-d6 
 = (0.91)	Depth: 19/52	00:05:36.23	476532kN (1417 KN/s, 69545 splits, 3799 aborts)

Count: Time: 336.297s, Nodes: 476602569 Qnodes: 331249088[69.5%][35.7%], NPS: 1417K
Hash:  TProbes: 476340679[99.9%] TPings: 207846457[43.6%] THits: 130202518[27.3%] TUsed: 67413749[94.5%]
EHash: KHits 222077353[98.5%] PHits 3472517[99.4%] POverall: 225549870[100.0%]
Exts:  Check: 10481695 Singular: 60180 Mate: 0 One-rep: 0 IID: 0[0.0%]
TB:    Probes: 220 Hits: 220[100.0%]
Idle:  CPU0: 70.748 CPU1: 69.563 CPU2: 14023.021 CPU3: 69.994




1. Re8xe4 Kg7-f8 2. Re4-e3 f7-f6 3. Re3-e6 Rd7-a7 4. c5-c6 Ra7-a2 5. Kh2-g3 Ra2-a3 6. Kg3-f2 Ra3-a2 7. Kf2-f3 Ra2-a3 8. Re6-e3 Ra3xe3 9. Kf3xe3 Kf8-e8 10. Ke3-d4 Ke8-d8 11. Kd4-d5 Kd8-e8 12. Kd5-e6 Ke8-d8 13. c6-c7 Kd8-c8 14. Ke6-e7 Kc8-b7 15. d6-d7 Kb7xc7 16. d7-d8=Q Kc7-c6 17. Qd8-a5 Kc6-b7 18. Ke7-d7 Kb7-b8 19. Kd7-c6 Kb8-c8 20. Qa5-c7 
 = (MAT20)	Depth: 21/62	00:02:37.29	676610kN (4301 KN/s, 937393 splits, 66757 aborts)
1. Re8xe4 Kg7-f8 2. Re4-e3 f7-f6 3. Re3-e6 Rd7-a7 4. c5-c6 Ra7-a2 5. Kh2-g3 Ra2-a3 6. Kg3-f2 Ra3-a2 7. Kf2-f3 Ra2-a3 8. Re6-e3 Ra3xe3 9. Kf3xe3 Kf8-e8 10. Ke3-d4 Ke8-d8 11. Kd4-d5 Kd8-e8 12. Kd5-e6 Ke8-d8 13. c6-c7 Kd8-c8 14. Ke6-e7 Kc8-b7 15. d6-d7 Kb7xc7 16. d7-d8=Q Kc7-c6 17. Qd8-a5 Kc6-b7 18. Ke7-d7 Kb7-b8 19. Kd7-c6 Kb8-c8 20. Qa5-c7 
 = (MAT20)	Depth: 21/62	00:03:08.92	814219kN (4310 KN/s, 975373 splits, 70784 aborts)
1. Re8xe4 Kg7-f6 2. Kh2-g3 Rd7-d8 3. Re4-e1 Kf6-g7 4. Re1-d1 Rd8-a8 5. d6-d7 Ra8-a3 6. Kg3-f2 Ra3-a2 7. Kf2-g1 Ra2-a8 8. d7-d8=Q Ra8xd8 9. Rd1xd8 Kg7-f6 10. c5-c6 Kf6-e5 11. c6-c7 Ke5-e4 12. c7-c8=Q Ke4-f3 13. Qc8-c4 Kf3-g3 14. Rd8-d3 Kg3-h4 15. Kg1-g2 f7-f6 16. Rd3-h3 
 = (MAT16)	Depth: 22/64	00:06:41.45	1259572kN (3138 KN/s, 1453714 splits, 82591 aborts)
1. Re8xe4 Kg7-f6 2. Kh2-g3 Rd7-d8 3. Re4-e1 Kf6-g7 4. Re1-d1 Rd8-a8 5. d6-d7 Ra8-a3 6. Kg3-f2 Ra3-a2 7. Kf2-g1 Ra2-a8 8. d7-d8=Q Ra8xd8 9. Rd1xd8 Kg7-f6 10. c5-c6 Kf6-e5 11. c6-c7 Ke5-e4 12. c7-c8=Q Ke4-f3 13. Qc8-c4 Kf3-g3 14. Rd8-d3 Kg3-h4 15. Kg1-g2 f7-f6 16. Rd3-h3 
 = (MAT16)	Depth: 22/64	00:06:59.54	1280118kN (3051 KN/s, 1453714 splits, 82591 aborts)
1. Re8xe4 Kg7-f6 2. Re4-e2 Rd7-d8 3. Re2-d2 Kf6-e5 4. d6-d7 Ke5-f4 5. c5-c6 Kf4-e3 6. c6-c7 Rd8-h8 7. Kh2-g3 Ke3xd2 8. c7-c8=Q Rh8xc8 9. d7xc8=Q Kd2-d3 10. Qc8-c5 Kd3-e4 11. f5-f6 Ke4-d3 12. Kg3-f3 Kd3-d2 13. Qc5-c4 Kd2-d1 14. Kf3-e3 Kd1-e1 15. Qc4-c1 
 = (MAT15)	Depth: 23/66	00:08:38.65	1422374kN (2742 KN/s, 1453714 splits, 82591 aborts)
1. Re8xe4 Kg7-f6 2. Re4-e2 Rd7-d8 3. Re2-d2 Kf6-e5 4. d6-d7 Ke5-f4 5. c5-c6 Kf4-e3 6. c6-c7 Rd8-h8 7. Kh2-g3 Ke3xd2 8. c7-c8=Q Rh8xc8 9. d7xc8=Q Kd2-d3 10. Qc8-c5 Kd3-e4 11. f5-f6 Ke4-d3 12. Kg3-f3 Kd3-d2 13. Qc5-c4 Kd2-d1 14. Kf3-e3 Kd1-e1 15. Qc4-c1 
 = (MAT15)	Depth: 23/66	00:09:33.54	1488238kN (2595 KN/s, 1453714 splits, 82591 aborts)
1. Re8xe4 Kg7-f6 2. Re4-e2 Rd7-d8 3. Re2-d2 Kf6-e5 4. d6-d7 Ke5-f4 5. c5-c6 Kf4-e3 6. c6-c7 Rd8-h8 7. Kh2-g3 Ke3xd2 8. c7-c8=Q Rh8xc8 9. d7xc8=Q Kd2-d3 10. Qc8-c5 Kd3-e4 11. f5-f6 Ke4-d3 12. Kg3-f3 Kd3-d2 13. Qc5-c4 Kd2-d1 14. Kf3-e3 Kd1-e1 15. Qc4-c1 
 = (MAT15)	Depth: 23/66	00:09:33.54	1488238kN (2595 KN/s, 1453714 splits, 82591 aborts)

Count: Time: 578.500s, Nodes: 1495745092 Qnodes: 962924366[64.4%][26.6%], NPS: 2586K
Hash:  TProbes: 1467865068[98.1%] TPings: 1209995014[82.4%] THits: 719808118[49.0%] TUsed: 69825655[97.9%]
EHash: KHits 403469033[97.9%] PHits 8629121[99.5%] POverall: 412098154[100.0%]
Exts:  Check: 73069416 Singular: 547844 Mate: 0 One-rep: 0 IID: 0[0.0%]
TB:    Probes: 0 Hits: 0[0.0%]
Idle:  CPU0: 1282.900 CPU1: 18896.330 CPU2: 1303.712 CPU3: 1284.893

[ernst]

Another example. During these events the cpu usage remains 99% for the engine.

Code: Select all

r - b - k b - r 
- - q n - p p - 
p - - p p n - p 
- - - - - - - - 
- p - N P - P - 
- - - - B P - - 
P P P Q N - - P 
- - K R - B - R 

WQC:0 WKC:0 BQC:1 BKC:1 Turn:WHITE EP:0
MB:     0 WPC: 7 BPC: 7 HM:2 HKL:B781CCE0 HKH:BCDA0DE

r1b1kb1r/2qn1pp1/p2ppn1p/8/1p1NP1P1/4BP2/PPPQN2P/2KR1B1R w kq - 2 1

Book: (0 entries / 0 bytes / 0s)
Book: No move selected.

1. Qd2xb4 e6-e5 2. Nd4-f5 d6-d5 3. Qb4-a4 g7-g6 4. g4-g5 g6xf5 5. g5xf6 
 = (0.62)	Depth: 9/31	00:00:00.42	885kN (2099 KN/s, 919 splits, 51 aborts)
1. Qd2xb4 e6-e5 2. Nd4-f5 d6-d5 3. Qb4-a4 g7-g6 4. g4-g5 g6xf5 5. g5xf6 
 = (0.62)	Depth: 9/32	00:00:00.59	1325kN (2231 KN/s, 1325 splits, 57 aborts)
1. Qd2xb4 e6-e5 2. Nd4-b3 d6-d5 3. Qb4-a4 d5-d4 4. Be3-d2 Bf8-d6 
 = (0.48)	Depth: 10/32	00:00:00.73	1685kN (2294 KN/s, 1495 splits, 69 aborts)
1. Qd2xb4 e6-e5 2. Nd4-b3 d6-d5 3. Qb4-a4 d5-d4 4. Be3-d2 
 = (0.48)	Depth: 10/32	00:00:01.40	3420kN (2433 KN/s, 2342 splits, 102 aborts)
1. Qd2xb4 e6-e5 2. Nd4-b3 d6-d5 3. Qb4-a4 d5-d4 4. Be3-d2 Bc8-b7 5. Nb3-a5 
 = (0.59)	Depth: 11/32	00:00:01.78	4357kN (2447 KN/s, 2655 splits, 137 aborts)
1. Qd2xb4 e6-e5 2. Nd4-b3 d6-d5 3. Qb4-a4 d5-d4 4. Be3-d2 Bc8-b7 5. Nb3-a5 
 = (0.59)	Depth: 11/32	00:00:02.21	5458kN (2460 KN/s, 3538 splits, 236 aborts)
1. Qd2xb4 d6-d5 2. Qb4-c3 Qc7xc3 3. Ne2xc3 e6-e5 4. e4xd5 e5xd4 5. Be3xd4 Ke8-d8 6. Bf1-c4 
 = (0.28)	Depth: 12/40	00:00:03.43	8752kN (2546 KN/s, 4431 splits, 304 aborts)
1. Qd2xb4 d6-d5 2. Qb4-c3 Qc7xc3 3. Ne2xc3 e6-e5 4. e4xd5 e5xd4 5. Be3xd4 Ke8-d8 6. Bf1-c4 
 = (0.28)	Depth: 12/41	00:00:08.73	23436kN (2683 KN/s, 6743 splits, 524 aborts)
1. Qd2xb4 d6-d5 2. Qb4-c3 Qc7xc3 3. Ne2xc3 e6-e5 4. Nc3xd5 Nf6xd5 5. e4xd5 e5xd4 6. Be3xd4 f7-f6 7. Bf1-d3 Ke8-d8 8. Rh1-e1 
 = (0.22)	Depth: 13/41	00:00:10.95	29362kN (2681 KN/s, 8469 splits, 646 aborts)
1. h2-h4 d6-d5 2. Bf1-g2 e6-e5 3. g4-g5 h6xg5 4. h4xg5 Rh8xh1 5. Rd1xh1 e5xd4 
 = (0.34)	Depth: 13/44	00:00:19.78	54053kN (2733 KN/s, 10489 splits, 814 aborts)
1. h2-h4 d6-d5 2. Bf1-g2 e6-e5 3. g4-g5 h6xg5 4. h4xg5 Rh8xh1 5. Rd1xh1 e5xd4 
 = (0.34)	Depth: 13/44	00:00:21.48	58719kN (2733 KN/s, 12495 splits, 1001 aborts)
1. h2-h4 d6-d5 2. Bf1-g2 Nd7-b6 3. b2-b3 Nf6-d7 4. f3-f4 Nd7-f6 5. e4xd5 Nb6xd5 6. g4-g5 h6xg5 7. h4xg5 Rh8xh1 8. Rd1xh1 
 = (0.35)	Depth: 14/46	00:00:29.26	80241kN (2742 KN/s, 15431 splits, 1188 aborts)
1. h2-h4 d6-d5 2. Bf1-g2 Nd7-b6 3. b2-b3 Nf6-d7 4. f3-f4 Nd7-f6 5. e4xd5 Nb6xd5 6. g4-g5 h6xg5 7. h4xg5 Rh8xh1 8. Rd1xh1 
 = (0.35)	Depth: 14/46	00:00:36.57	100753kN (2754 KN/s, 20683 splits, 1589 aborts)
1. h2-h4 d6-d5 2. e4xd5 Nf6xd5 3. Ne2-f4 Bc8-b7 4. Nf4xd5 Bb7xd5 5. Kc1-b1 Bf8-c5 6. Bf1-d3 Nd7-e5 7. Bd3-e4 Ne5-c4 
 = (0.19)	Depth: 15/50	00:00:53.21	149071kN (2801 KN/s, 26543 splits, 2109 aborts)
1. Qd2xb4 d6-d5 2. Qb4-c3 Qc7xc3 3. Ne2xc3 e6-e5 4. Nc3xd5 Nf6xd5 5. e4xd5 e5xd4 6. Be3xd4 f7-f6 7. Bf1-d3 Bf8-b4 8. c2-c3 
 = (0.23)	Depth: 15/50	00:01:22.11	193690kN (2359 KN/s, 32345 splits, 2603 aborts)
1. Qd2xb4 d6-d5 2. Qb4-c3 Qc7xc3 3. Ne2xc3 e6-e5 4. Nc3xd5 Nf6xd5 5. e4xd5 e5xd4 6. Be3xd4 f7-f6 7. Bf1-d3 Bf8-b4 8. c2-c3 
 = (0.23)	Depth: 15/50	00:03:29.26	286329kN (1368 KN/s, 32345 splits, 2603 aborts)

Count: Time: 212.781s, Nodes: 289187802 Qnodes: 214414419[74.1%][43.2%], NPS: 1359K
Hash:  TProbes: 289161394[100.0%] TPings: 81198884[28.1%] THits: 49033058[17.0%] TUsed: 71207668[99.9%]
EHash: KHits 160013149[92.5%] PHits 6800493[52.1%] POverall: 166813642[96.4%]
Exts:  Check: 1353173 Singular: 17809 Mate: 0 One-rep: 0 IID: 0[0.0%]
TB:    Probes: 0 Hits: 0[0.0%]
Idle:  CPU0: 67.791 CPU1: 7830.844 CPU2: 63.022 CPU3: 65.756

[Koroljow]

I have observed some of this behavior: Kn/sec drops and the CPU usage drops. This has happened when analyzing the same position for ~20-30 minutes.

Furthermore, when using Zappa Mexico 2 in Chessbase's blundercheck mode, sometimes (three times in five attempts) the program will enter a zombie state (minimal CPU usage, but a high Kn/sec value). Exiting blundercheck leaves the program in this state, and it must be reloaded. I have not seen this with the original Zappa Mexico (five runs or so).

I also use an overclocked q6600 with core temperatures in the low 50's.

The best,

Walter

[Spock]

I'm not sure if it is similar - but Deep Junior 10 on a quad also does something similar - doesn't always use all 4 cores

[M ANSARI]

I can confirm that Rybka does the same ... I used to think it was TB hits but I have seen this in non endgame positions. It seems one core drops from 100% and then the other cores are somehow affected ... it still plays strong but not as strong as it should. I had the feeling it was what was causing Rybka to not scale well but now it seems that other programs have the same problem. I am not sure what it is, but it could be something to do with a problem when hashtables get filled up and some sort of latency when manipulating large hash tables. But I have noticed it several times and was planning to hypersnap a pic of this behaviour and sending it to Vas.

[ernst]

I have observed some of this behavior: Kn/sec drops and the CPU usage drops. This has happened when analyzing the same position for ~20-30 minutes.

Furthermore, when using Zappa Mexico 2 in Chessbase's blundercheck mode, sometimes (three times in five attempts) the program will enter a zombie state (minimal CPU usage, but a high Kn/sec value). Exiting blundercheck leaves the program in this state, and it must be reloaded. I have not seen this with the original Zappa Mexico (five runs or so).

I also use an overclocked q6600 with core temperatures in the low 50's.

The best,

Walter

I see Zappa ztill use 99% cpu time when this happens. When you see this again, could you please check zappa_log.txtx for CPU idle times? Thanks.

[ernst]

I'm not sure if it is similar - but Deep Junior 10 on a quad also does something similar - doesn't always use all 4 cores

This is correct but you'll see Junior CPU usage vary with it. In my case the CPU time remains 99%.

[ernst]

I can confirm that Rybka does the same ... I used to think it was TB hits but I have seen this in non endgame positions. It seems one core drops from 100% and then the other cores are somehow affected ... it still plays strong but not as strong as it should. I had the feeling it was what was causing Rybka to not scale well but now it seems that other programs have the same problem. I am not sure what it is, but it could be something to do with a problem when hashtables get filled up and some sort of latency when manipulating large hash tables. But I have noticed it several times and was planning to hypersnap a pic of this behaviour and sending it to Vas.

Rybka's display of speed is a case on it's own I guess.