Problem with pipes

[bob]

I occasionally run with debugging on which sends a _ton_ of stuff to stdout, and xboard just merrily ignores it and keeps right on working... How does sending a lot of stuff _from_ your program make your receiving a stop command slow? Xboard uses two pipes and one won't affect how the other behaves...

Could it be because of the commands I am using?
For sending I use printf() and for receiving I use gets();

I just checked the Crafty source code and you don't seem to use those.

printf() is ok if you do a fflush() after each one.

gets() is a no-no. The problem is this:

The O/S kernel has a buffer space where data is collected until a program reads it. But in your case, the C library reads all the data in the buffer and gives you the first string up to \n. If you then ask "is any more data left?" you get a "no" because the operating system looks at its own buffer, which is empty, and doesn't know that the C library buffer has stuff you have not yet processed.

The engine-intf document in xboard describes this in detail. Best solution is to use read() to read data as that is not a buffered library call and avoids the problem... But it introduces a few issues of its own. Again the interface doc from xboard/winboard will tell you what to do.

[bob]

... for receiving I use gets();

Get rid of it immediately.

Thats not the problem though. I guess it's an OS issue

Actually it is the problem because it is a buffered I/O call and after using it to read one line, you can't then ask the O/S "Is there more data in your buffer?" because gets() read it all and has it in its own buffer space...

the xboard engine-intf document explains all this in gorey detail as Tim Mann and I worked on describing the problem in great detail.

[bob]

Xboard uses two pipes and one won't affect how the other behaves...

But XBoard does not use PeekNamedPipe, of course... So this is not really relevant.

But his program does. So he is having problems seeing any sort of command sent _to_ his engine... Because of the buffered I/O breaking either PeekNamedPipe ()windoze) or select(unix).

[Edmund]

I changed gets() to read() ... still not quite working .. here is my communication code:

Code: Select all

// Com first reads all new commands and if task (my abort-flag) is still true, send available info-lines
//com is called every 0x7FF node and every time a new pv is found. (the new pv is copied to the end of towrite first)
void com() {

	char command[65536];


	if (!pipe) {
		if (com_input()) {
			gets(command);
		} else {
			goto sendData;
		}
	} else {
		if (com_input()) {
			U32 oldbytes = strlen(toread);
			U32 bytes = read(fileno(stdin), toread+oldbytes, 65536);
			toread[bytes+oldbytes] = 0;
		}

		if (!strchr(toread, '\n')) goto sendData;

		memcpy(command, toread, strlen(toread)+1);
		memcpy(toread, strchr(command, '\n') + 1, strlen(strchr(command, '\n')));
		*strchr(command, '\n') = 0;
	}

    if (!strcmp (command, "uci"))			com_uci();
    if (!strcmp (command, "isready"))		com_isready();
    if (!strncmp(command, "setoption", 9))	options_set(command);
    if (!strcmp (command, "ucinewgame"))	com_ucinewgame();
    if (!strncmp(command, "position", 8))	com_position(command);
    if (!strncmp(command, "go", 2))			com_go(command);
    if (!strncmp(command, "debug", 5)) 		options_set(command);
    if (!strcmp (command, "ponderhit"))     time_ponderhit();
	if (!strcmp (command, "stop"))	        com_stop();
    if (!strcmp (command, "quit"))	        exit(0);

	if (!strncmp(command, "perft", 5))		util_perft_start(command);
	if (!strncmp(command, "bench", 5))		util_bench(command);
	if (!strcmp (command, "d"))				board_display();
	if (!strcmp (command, "new"))			algeb_fen(STARTFEN);
	if (!strncmp(command, "fen", 3))		algeb_fen(command+4);
	if (!strncmp(command, "move", 4))		algeb_moves(command+5);
	if (!strcmp (command, "eval"))			eval_print();

sendData:

	if (task) {
		com_writebuffer();
	}
}

// writebuffer sends all info-lines together in one block. option.buffer is set to 300
void com_writebuffer() {
	if (!task || !(*towrite || *towrite_curline || *towrite_curmove || *towrite_hashfull)) return;

	U64 time = gettime();
	if ((time-lastwrite) > options.buffer) {
		strcat(towrite, towrite_curline);
		strcat(towrite, towrite_curmove);
		strcat(towrite, towrite_hashfull);	
		printf("info string Start Sending Info-Block\n");
		printf("%s", towrite);
		printf("info string Finished Sending Info-Block\n");
		fflush(stdout);
		lastwrite = time;
		com_resetBuffer();
	}
}

And here is the Arena Output after running the WAC test at 1 sec/pos with Automatic Analysis starting in position 14 and ending position 15

Code: Select all

1.085.547-->1:position fen r2rb1k1/pp1q1p1p/2n1p1p1/2bp4/5P2/PP1BPR1Q/1BPN2PP/R5K1 w - - 0 1
1.085.547-->1:go infinite
1.085.547<--1:info string Start Sending Info-Block
1.085.547<--1:info depth 1 currmove d2e4 currmovenumber 1 nodes 1
1.085.547<--1:info string Finished Sending Info-Block
1.085.861<--1:info string Start Sending Info-Block
1.085.861<--1:info depth 1 score cp -261 time 0 nodes 4 nps 0 pv d2e4
1.085.875<--1:info depth 1 score cp -116 time 0 nodes 11 nps 0 pv b2d4
1.085.875<--1:info depth 1 score cp -84 time 0 nodes 14 nps 0 pv b2e5
1.085.891<--1:info depth 1 score cp -21 time 0 nodes 28 nps 0 pv a1e1
1.085.908<--1:info depth 1 score cp -16 time 0 nodes 29 nps 0 pv a1d1
1.085.908<--1:info depth 1 score cp -15 time 0 nodes 32 nps 0 pv b2f6
1.085.923<--1:info depth 2 score cp 1 time 0 nodes 122 nps 0 pv b2f6 d8c8
1.085.923<--1:info depth 3 score cp -9 time 0 nodes 609 nps 0 pv b2f6 c5e7 f6e7
1.085.938<--1:info depth 3 score cp 279 time 16 nodes 6636 nps 414750 pv h3h7 g8f8 h7g7 f8e7 b2f6 e7d6 f6d8 a8d8
1.085.938<--1:info depth 4 score cp 277 time 63 nodes 32000 nps 507936 pv h3h7 g8f8 h7h8 f8e7 b2f6 e7d6 f6d8 a8d8 c2c3
1.085.955<--1:info depth 5 currmove h3h7 currmovenumber 1 nodes 37606
1.085.955<--1:info string Finished Sending Info-Block
1.086.173<--1:info string Start Sending Info-Block
1.086.173<--1:info depth 5 score cp 438 time 469 nodes 218248 nps 465347 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 a1e1
1.086.188<--1:info depth 6 score mate 4 time 469 nodes 224705 nps 479115 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 h7g7
1.086.204<--1:info depth 7 score mate 4 time 485 nodes 237406 nps 489496 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 h7g7
1.086.219<--1:info depth 8 score mate 4 time 516 nodes 290394 nps 562779 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 h7g7
1.086.219<--1:info depth 9 score mate 4 time 532 nodes 294526 nps 553620 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 h7g7
1.086.236<--1:info depth 9 currmove c2c3 currmovenumber 38 nodes 368067
1.086.236<--1:info string Finished Sending Info-Block
1.086.486<--1:info string Start Sending Info-Block
1.086.486<--1:info depth 10 score mate 4 time 625 nodes 374995 nps 599992 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 h7g7
1.086.516<--1:info depth 11 score mate 4 time 688 nodes 429679 nps 624533 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 h7g7
1.086.532<--1:info depth 12 score mate 4 time 782 nodes 504255 nps 644827 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 h7g7
1.086.564-->1:stop
1.088.314-->1:stop
1.088.407-->1:stop
1.089.033<--1:info depth 13 score mate 4 time 813 nodes 578649 nps 711745 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 h7g7
1.089.048<--1:info depth 14 score mate 4 time 828 nodes 595579 nps 719298 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 h7g7
1.089.048<--1:info depth 15 score mate 4 time 860 nodes 669976 nps 779041 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 h7g7
1.089.048<--1:info depth 16 score mate 4 time 891 nodes 744371 nps 835433 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 h7g7
1.089.048<--1:info depth 16 currmove h3h4 currmovenumber 40 nodes 812757
1.089.048<--1:info string Finished Sending Info-Block

What I take from this is that it took way too long to transmit the last Info-Block.

So I ran another test on the same position with the writing buffer disabled.

Code: Select all

[...]
1.988.720<--1:info depth 10 currmove h3g3 currmovenumber 46 nodes 425525
1.988.720<--1:info depth 11 currmove h3h7 currmovenumber 1 nodes 425662
1.988.720<--1:info depth 11 score mate 4 time 922 nodes 429679 nps 466029 pv h3h7 g8f8 b2f6 c5e3 f3e3 d8c8 h7g7
1.988.736<--1:info depth 11 currmove h3h6 currmovenumber 2 nodes 429679
1.988.736<--1:info depth 11 currmove h3e6 currmovenumber 3 nodes 433095
1.988.736<--1:info depth 11 currmove d2e4 currmovenumber 4 nodes 437773
1.988.736<--1:info depth 11 currmove f3g3 currmovenumber 5 nodes 441131
1.988.736<--1:info depth 11 currmove d3g6 currmovenumber 6 nodes 444055
1.988.736<--1:info depth 11 currmove a3a4 currmovenumber 7 nodes 446914
1.988.736<--1:info depth 11 currmove b2f6 currmovenumber 8 nodes 450060
1.988.736<--1:info depth 11 currmove g1f2 currmovenumber 9 nodes 452737
1.988.751<--1:info depth 11 currmove b3b4 currmovenumber 10 nodes 455506
1.988.751<--1:info depth 11 currmove f3f2 currmovenumber 11 nodes 458389
1.988.751<--1:info depth 11 currmove h3f5 currmovenumber 12 nodes 461158
1.988.751<--1:info depth 11 currmove f3f1 currmovenumber 13 nodes 463877
1.988.766<--1:info depth 11 currmove g2g4 currmovenumber 14 nodes 466400
1.988.766<--1:info depth 11 currmove g1h1 currmovenumber 15 nodes 468804
1.988.766<--1:info depth 11 currmove b2e5 currmovenumber 16 nodes 470986
1.988.766<--1:info depth 11 currmove f4f5 currmovenumber 17 nodes 472925
1.988.766<--1:info depth 11 currmove a1e1 currmovenumber 18 nodes 475174
1.988.783<--1:info depth 11 currmove g2g3 currmovenumber 19 nodes 476850
1.988.783<--1:info depth 11 currmove b2d4 currmovenumber 20 nodes 478768
1.988.783-->1:stop
1.988.783<--1:info depth 11 currmove b2g7 currmovenumber 21 nodes 480386
1.988.798<--1:info depth 11 currmove a1d1 currmovenumber 22 nodes 481952
1.990.564-->1:stop
1.990.673-->1:stop

without buffering sending seems to go quicker .. still Arena is not happy at all about the Engine to send 2 more lines after the stop command -> resulting in the next position not to be displayed.

[bob]

Couple of things.

(1) I don't do UCI so I am not familiar with the protocol specifications. Is it acceptable to send information after a stop is received? I'd hope so because of the simple race condition that exists if this is not allowed.

(2) I would not do write buffering at all. What's the point? The system already does this internally and you are just duplicating this functionality.

The biggest issue with using read() is this: You can receive multiple commands in one read, and more importantly you can receive a _partial_ command as well, because read returns the "byte-count" (which you specify) bytes if available, or else everything it has if available_data < byte_count. That last command can be a pain because it takes another read to get the remainder of the command. I could not see that you handle this case.

[Edmund]

(1) I don't do UCI so I am not familiar with the protocol specifications. Is it acceptable to send information after a stop is received? I'd hope so because of the simple race condition that exists if this is not allowed.

I just checked with some other UCI engines .. it seems alright to send some lines a couple of milliseconds later. But in my tests Arena sent a second and third "Stop" after about one second. And only after then did the engine realize the command and answer with the requested bestmove. Only then according to the UCI protocol is the calculation terminated. Anyway, this was too late for Arena.

The biggest issue with using read() is this: You can receive multiple commands in one read, and more importantly you can receive a _partial_ command as well, because read returns the "byte-count" (which you specify) bytes if available, or else everything it has if available_data < byte_count. That last command can be a pain because it takes another read to get the remainder of the command. I could not see that you handle this case.

I dealt with this problem .. probably not the finest way, but it was a quick solution that seems to work.

Code: Select all

      if (com_input()) {
         U32 oldbytes = strlen(toread);
         U32 bytes = read(fileno(stdin), toread+oldbytes, 65536);
         toread[bytes+oldbytes] = 0;
      }

      if (!strchr(toread, '\n')) goto sendData;

      memcpy(command, toread, strlen(toread)+1);
      memcpy(toread, strchr(command, '\n') + 1, strlen(strchr(command, '\n')));
      *strchr(command, '\n') = 0; 

1) if new input arrives, append it to 'toread'
2) if no \n in 'toread' return
3) copy 'toread' to 'command'
4) copy 'command' to 'toread' starting at the linebreak + 1 (so if there was just one command in the first place copy a 0 to 'toread'
5) replace the first \n in 'command' with a 0

so it can never happen that any half empty commands are processed because 1) and 2) would only pass if a \n is in the string.[/code]

[bob]

(1) I don't do UCI so I am not familiar with the protocol specifications. Is it acceptable to send information after a stop is received? I'd hope so because of the simple race condition that exists if this is not allowed.

I just checked with some other UCI engines .. it seems alright to send some lines a couple of milliseconds later. But in my tests Arena sent a second and third "Stop" after about one second. And only after then did the engine realize the command and answer with the requested bestmove. Only then according to the UCI protocol is the calculation terminated. Anyway, this was too late for Arena.

The biggest issue with using read() is this: You can receive multiple commands in one read, and more importantly you can receive a _partial_ command as well, because read returns the "byte-count" (which you specify) bytes if available, or else everything it has if available_data < byte_count. That last command can be a pain because it takes another read to get the remainder of the command. I could not see that you handle this case.

I dealt with this problem .. probably not the finest way, but it was a quick solution that seems to work.

Code: Select all

      if (com_input()) {
         U32 oldbytes = strlen(toread);
         U32 bytes = read(fileno(stdin), toread+oldbytes, 65536);
         toread[bytes+oldbytes] = 0;
      }

      if (!strchr(toread, '\n')) goto sendData;

      memcpy(command, toread, strlen(toread)+1);
      memcpy(toread, strchr(command, '\n') + 1, strlen(strchr(command, '\n')));
      *strchr(command, '\n') = 0; 

1) if new input arrives, append it to 'toread'
2) if no \n in 'toread' return
3) copy 'toread' to 'command'
4) copy 'command' to 'toread' starting at the linebreak + 1 (so if there was just one command in the first place copy a 0 to 'toread'
5) replace the first \n in 'command' with a 0

so it can never happen that any half empty commands are processed because 1) and 2) would only pass if a \n is in the string.[/code]

That's exactly what I do. But beware of the hidden buffering problem, which it sounds like you are. That is you can receive several commands at one time, and the "peekNamedPipe()" will only tell you once that you have data because you grab it in one big gulp, and you then have to make sure you handle every command in the buffer in some way before returning.

That took some tweaking when I first started doing this with xboard back in 1995.

[Tony]

The probleem does not seem to be the reading of the stop command, but responding to it. How fast does your engine stop after receiving it ?

Some people try to save time by only checking the stop condition at the top of the searchfunctions, wich slows down stopping seriously.
Tony

[bob]

The probleem does not seem to be the reading of the stop command, but responding to it. How fast does your engine stop after receiving it ?

Some people try to save time by only checking the stop condition at the top of the searchfunctions, wich slows down stopping seriously.
Tony

really should not hurt since things are recursive. This should see the stop condition at least once every node...

[sje]

In the first version of Symbolic, I used anonymous pipes for inter-thread communication and I found out rather late in the game that writing to a pipe can block the calling thread. In fact, it's guaranteed to block if the pipe is fixed length (often just one 512 byte long block) and the consumer end isn't keeping up with the producer. This is one reason why you never want a signal handler to write to an anonymous pipe, or perhaps to any other kind of pipe.



Trivia: Did you know that "pipe", in colloquial French, is slang for "fellatio"?