Why my C function is called twice?

A very simple C function which I copied from the manual.
And I found that it's called twice.

Even in the function:

if (SRF_IS_FIRSTCALL()) {
ereport(INFO, (errcode(ERRCODE_IO_ERROR), errmsg("1")));
}

An example output. You will find two INFO: 1 there......

Why a function is called twice and how to prevent this problem?

Thanks

Billow

test=# select * from retcomposite(1,48);
INFO: 1
INFO: 2
INFO: 3
INFO: 1
INFO: 4
INFO: 2
INFO: 2
INFO: 5
INFO: 3
INFO: 4
INFO: 2
INFO: 5
f1 | f2 | f3
----+----+-----
48 | 96 | 144
(1 row)

===============================================================
Code......
===============================================================
/*
CREATE OR REPLACE FUNCTION retcomposite(integer, integer)
RETURNS SETOF __retcomposite
AS 'test.so', 'retcomposite'
LANGUAGE C IMMUTABLE STRICT;
*/

// PostgreSQL includes
#include "postgres.h"
#include "fmgr.h"

// Tuple building functions and macros
#include "access/heapam.h"
#include "funcapi.h"
#include "utils/builtins.h"

#include <sys/socket.h>
#include <fcntl.h>
#include <errno.h>
#include <sys/select.h>

#define _textout(str) DatumGetPointer(DirectFunctionCall1(textout,
PointerGetDatum(str)))

#ifdef PG_MODULE_MAGIC
PG_MODULE_MAGIC;
#endif

PG_FUNCTION_INFO_V1(retcomposite);

Datum
retcomposite(PG_FUNCTION_ARGS)
{
FuncCallContext *funcctx;
int call_cntr;
int max_calls;
TupleDesc tupdesc;
AttInMetadata *attinmeta;

/* stuff done only on the first call of the function */
if (SRF_IS_FIRSTCALL()) {
MemoryContext oldcontext;

ereport(INFO, (errcode(ERRCODE_IO_ERROR), errmsg("1")));

/* create a function context for cross-call persistence
*/
funcctx = SRF_FIRSTCALL_INIT();

/* switch to memory context appropriate for multiple
function calls */
oldcontext =
MemoryContextSwitchTo(funcctx->
multi_call_memory_ctx);

/* total number of tuples to be returned */
funcctx->max_calls = PG_GETARG_UINT32(0);

/* Build a tuple descriptor for our result type */
if (get_call_result_type(fcinfo, NULL, &tupdesc) !=
TYPEFUNC_COMPOSITE)
ereport(ERROR,
(errcode(ERRCODE_FEATURE_NOT_SUPPORTED),
errmsg
("function returning record called in context "
"that cannot accept type record")));

/* generate attribute metadata needed later to produce
tuples from raw C strings */
attinmeta = TupleDescGetAttInMetadata(tupdesc);
funcctx->attinmeta = attinmeta;

MemoryContextSwitchTo(oldcontext);
}

ereport(INFO, (errcode(ERRCODE_IO_ERROR), errmsg("2")));

/* stuff done on every call of the function */
funcctx = SRF_PERCALL_SETUP();

call_cntr = funcctx->call_cntr;
max_calls = funcctx->max_calls;
attinmeta = funcctx->attinmeta;

if (call_cntr < max_calls) { /* do when there is more
left to send */
char **values;
HeapTuple tuple;
Datum result;
ereport(INFO, (errcode(ERRCODE_IO_ERROR), errmsg("3")));

/* Prepare a values array for building the returned
tuple. This should be an array of C strings which
will be processed later by the type input functions. */
values = (char **) palloc(3 * sizeof(char *));
values[0] = (char *) palloc(16 * sizeof(char));
values[1] = (char *) palloc(16 * sizeof(char));
values[2] = (char *) palloc(16 * sizeof(char));

snprintf(values[0], 16, "%d", 1 * PG_GETARG_INT32(1));
snprintf(values[1], 16, "%d", 2 * PG_GETARG_INT32(1));
snprintf(values[2], 16, "%d", 3 * PG_GETARG_INT32(1));

/* build a tuple */
tuple = BuildTupleFromCStrings(attinmeta, values);

/* make the tuple into a datum */
result = HeapTupleGetDatum(tuple);

/* clean up (this is not really necessary) */
pfree(values[0]);
pfree(values[1]);
pfree(values[2]);
pfree(values);

ereport(INFO, (errcode(ERRCODE_IO_ERROR), errmsg("4")));

SRF_RETURN_NEXT(funcctx, result);
} else { /* do when there is no more left */
ereport(INFO, (errcode(ERRCODE_IO_ERROR), errmsg("5")));

SRF_RETURN_DONE(funcctx);
}
}