Reduction in running time of multiple modules due to linking

Question

This question may seem very vague, hence I have included the code snippets for the modules mentioned. I have written a program that collects data from various sensors on an I2C bus and stores the formatted values in a file. This shall run on an ARM cortex A9 processor (single core) in an SoC configuration called Zedboard by Xilinx, and uses the petalinux operating system with the vanilla linux kernel. The time is being measured using clock_gettime(). I have noticed significant reduction in a single sensor access time when all of the sensors are being accessed sequentially within a single process. The comparison of this time was done with that of individual processes that access a single sensor only and do not write the data to a file, but print it to stdout instead.

Sensors used along with modules:

GY521 Module:

    #include <linux/i2c-dev-user.h>
    #include <stdio.h>
    #include <stdlib.h>
    #include <sys/ioctl.h>
    #include <unistd.h>
    #include <fcntl.h>
    #include <stdint.h>
    #include <inttypes.h>
    #include "GY521.h"
    #include <time.h>

    #define ADDR 0x68

    static int file;
    static __s32 res;
    static __u8 reg;
    static __u8 values[14];   //array to hold all the register values

    void set_sleep_gy521(int flag)
    {
        if(flag==0)    //wake up the device
        {
            //Accessing reg 107
            reg = 0x6B;
            uint8_t val8 = 0x01;     //write 0x00 if you want to set the internal 8MHz oscillator as CLK                                              
            res = i2c_smbus_write_byte_data(file, reg, val8);
            if(res<0) 
                perror("Failed to wake it up");
            /*else 
                printf("Device is awake\n");*/
        }
        else      //set it to sleep
        {
            reg = 0x6B;
            uint8_t val8 = 0x41;   //write 0x40 if you want to set the internal 8MHz oscillator as CLK                                             
            res = i2c_smbus_write_byte_data(file, reg, val8);
            if(res<0) 
                perror("Failed to go to sleep");
            /*else 
                printf("In sleep mode\n");*/
        }
    }

    void init_gy521()
    {
        char filename[20];
        int adapter_no = 0;
        snprintf(filename, 19, "/dev/i2c-%d", adapter_no);
        file = open(filename, O_RDWR);
        if(file<0)
        {
            perror("File not opened");  
            exit(1);
        }
        if(ioctl(file, I2C_SLAVE, ADDR)<0)
        {
            perror("Not able to access the device");
            exit(EXIT_FAILURE);
        }

        //setting the sensitivity of the gyroscope and accelerometer

        res = i2c_smbus_write_byte_data(file, 0x1B, 0x00);
        if(res<0)
            perror("Failed to set gyro range");
        res = i2c_smbus_write_byte_data(file, 0x1C, 0x00);
        if(res<0)
            perror("Failed to set the accelerometer range");

        set_sleep_gy521(0);  //this also sets the clock source to X-axis gyro reference which is slightly better than the internal 8MHz oscillator
    }

    //get_values() stores all the register measurements in the array values

    int get_values()
    {
        //reading all the values needed at once in a block
        res = i2c_smbus_read_i2c_block_data(file, 0x3B, 14, (__u8*)values);     
        if(res<0)
            perror("Failed to read using Block");
        return res;
    }

    float get_Ax()
    {
        int c = get_values();      //calls get_values() to get all values at a time instant
        int16_t xout;
        if(c>0)
            xout = (((int16_t)values[0])<<8) | values[1];
        else
        {   
            perror("Can't get the values");
            exit(EXIT_FAILURE); 
        }
        return xout/16384.0*9.8;
    }

    float get_Ay()
    {   
        //concatenate the higher byte and the lower byte
        int16_t yout = (((int16_t)values[2])<<8) | values[3];
        return yout/16384.0*9.8;
    }

    float get_Az()
    {
        int16_t zout = (((int16_t)values[4])<<8) | values[5];
        return zout/16384.0*9.8;
    }

    float get_temp_gy521()
    {
        __s16 temp = (((int16_t)values[6])<<8) | values[7];
        return (temp/340.0 + 36.53);    
    }

    float get_Wx()
    {
        __s16 xgyro = (((int16_t)values[8])<<8) | values[9]; 
        return xgyro/131.0;
    }
    float get_Wy()
    {
        __s16 ygyro = (((int16_t)values[10])<<8) | values[11]; 
        return ygyro/131.0;
    }

    float get_Wz()
    {
        __s16 zgyro = (((int16_t)values[12])<<8) | values[13]; 
        return zgyro/131.0;
    }

    void clear_gy521()
    {
        close(file);
    }

    int main()
    {
        struct timespec start, end;
        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &start);
        init_gy521();
        printf("Wx: %f\n", get_Wx());
        printf("Wy: %f\n", get_Wy());
        printf("Wz: %f\n", get_Wz());
        printf("Ax: %f\n", get_Ax());
        printf("Ay: %f\n", get_Ay());
        printf("Az: %f\n", get_Az());
        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &end);
        printf("Time taken by GY521 is %d MuS\n", (end.tv_sec-start.tv_sec)*1000000L+(end.tv_nsec-start.tv_nsec)/1000);
    }

LM75 Module:

    #include <linux/i2c-dev-user.h>
    #include <stdlib.h>
    #include <stdio.h>
    #include <unistd.h>
    #include <sys/ioctl.h>
    #include <fcntl.h>
    #include <time.h>

    #define ADDRESS 0x48

    static int file;        //use static keyword to ensure that the scope of this variable is limited to this file.
    static __u8 buffer[2];


    int get_temp()
    {
        if(i2c_smbus_read_i2c_block_data(file, 0x00, 2, buffer)<0)
            perror("Failed to read the block");
        return buffer[0]&127;
    }

    //Initializes the file used by the userspace calls. [IMPORTANT] Must be run before any other function is called for this device!. This needs to be called only once for each process.
    void init_LM75()
    {
        int adapter_number = 0;     //check this.
        char filename[20];
        snprintf(filename, 19, "/dev/i2c-%d", adapter_number);
        file = open(filename, O_RDWR);
        if(file<0)
        {
            perror("File not opened");
            exit(1);
        }
        if(ioctl(file, I2C_SLAVE, ADDRESS)<0)
        {
            perror("ioctl could not open file");
            exit(1);
        }
    }

    int main()
    {
        struct timespec start, end;
        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &start);    
        init_LM75();
        printf("Temperature is %d\n", get_temp());
        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &end);
        printf("Time taken %d\n", (end.tv_sec-start.tv_sec)*1000000L+(end.tv_nsec-start.tv_nsec)/1000);
    }

HMC5883L Module:

    #include <linux/i2c-dev-user.h>
    #include <stdlib.h>
    #include <stdio.h>
    #include <unistd.h>
    #include <sys/ioctl.h>
    #include <fcntl.h>
    #include "HMC5883L.h"
    #include <time.h>

    #define ADDRESS 0x1e

    static int file;        //use static keyword to ensure that the scope of this variable is limited to this file.
    static float factor;
    static __u8 buffer[6];

    //register addresses
    __u8 config_reg_A = 0x00;
    __u8 mode_reg = 0x02;
    __u8 gain_reg = 0x01;
    __u8 data_X_H = 0x03;
    __u8 data_X_L = 0x04;
    __u8 data_Y_H = 0x07;
    __u8 data_Y_L = 0x08;
    __u8 data_Z_H = 0x05;
    __u8 data_Z_L = 0x06;



    /** 
    *   The value of mode must be according to the following table:
    *   Value       Mode
    *   0           Continuous
    *   1           Single  (Default)
    *   2           Idle
    *   3           Idle
    *
    *   After any mode change care must be taken to set it back to continuous mode before reading any values.
    **/
    void set_magnetometer_mode(int mode)
    {
        __u8 value = 0x00;
        value |= mode;
        if(i2c_smbus_write_byte_data(file, mode_reg, value)<0)
            perror("Failed to change magnetometer mode");
    }

    void get_B()
    {
        if(i2c_smbus_read_i2c_block_data(file, data_X_H, 6, buffer)<0)
            perror("Failed to read the block");
    }

    //[IMPORTANT] Note that  the following 3 functions will return the field values in milli gauss by reading them from the buffer. So call get_Bx() first!
    float get_Bx()
    {   
        get_B();
        int16_t temp;
        //concatenate the upper and lower bits
        temp = buffer[0];
        int16_t b_X = (temp<<8) | buffer[1];
        return (float)b_X*factor;
    }

    float get_By()
    {
        int16_t temp;
        //concatenate the upper and lower bits
        temp = buffer[4];
        int16_t b_Y = (temp<<8) | buffer[5];
        return (float)b_Y*factor;
    }

    float get_Bz()
    {
        int16_t temp;
        //concatenate the upper and lower bits
        temp = buffer[2];
        int16_t b_Z = (temp<<8) | buffer[3];
        return (float)b_Z*factor;
    }

    //Initializes the file used by the userspace calls. [IMPORTANT] Must be run before any other function is called for this device!. This needs to be called only once for each process.
    void init_magnetometer()
    {
        int adapter_number = 0;     //check this.
        char filename[20];
        snprintf(filename, 19, "/dev/i2c-%d", adapter_number);
        file = open(filename, O_RDWR);
        if(file<0)
        {
            perror("File not opened");
            exit(1);
        }
        if(ioctl(file, I2C_SLAVE, ADDRESS)<0)
        {
            perror("ioctl could not open file");
            exit(1);
        }
        factor = 0.92;
        set_magnetometer_mode(0);
    }

    void clear_magnetometer()
    {
        close(file);
    }

    /** 
    *   The value of freq must be according to the following table:
    *   Value       Rate (Hz)
    *   0           0.75
    *   1           1.5
    *   2           3
    *   3           7.5
    *   4           15      (Default)
    *   5           30
    *   6           75
    **/
    void set_magnetometer_frequency(int freq)
    {
        __u8 value = 0x00;
        value |= freq<<2;
        if(i2c_smbus_write_byte_data(file, config_reg_A, value)<0)
            perror("Failed to change data rate");
    }


    /** 
    *   The value of gain must be according to the following table:
    *   Value       Field Range (+/- Gauss)
    *   0           0.88
    *   1           1.3     (Default)
    *   2           1.9
    *   3           2.5
    *   4           4.0
    *   5           4.7
    *   6           5.6
    *   7           8.1
    *   
    *   This function will also set the value of the factor to be multiplied to the raw data.
    **/
    void set_magnetometer_gain(int gain)
    {
        __u8 value = 0x00;
        value |= gain<<5;
        if(i2c_smbus_write_byte_data(file, gain_reg, value)<0)
            perror("Failed to change magnetometer gain");
        else
        {
            switch(gain)
            {
                case 0: factor = 0.73; break;
                case 1: factor = 0.92; break;
                case 2: factor = 1.22; break;
                case 3: factor = 1.52; break;
                case 4: factor = 2.27; break;
                case 5: factor = 2.56; break;
                case 6: factor = 3.03; break;
                case 7: factor = 4.35; break;
            }
        }
    }

    int main()
    {
        struct timespec start, end;
        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &start);
        init_magnetometer();
        printf("%f\t%f\t%f\n", get_Bx(), get_By(), get_Bz());
        clear_magnetometer();
        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &end);
        printf("Time taken by HMC is %d MuS\n", (end.tv_sec-start.tv_sec)*1000000L+(end.tv_nsec-start.tv_nsec)/1000);
    }

Single module that clubs all the three together and also writes data in a file:

    #include <stdio.h>
    #include <stdlib.h>
    #include "hwfunctions.h"
    #include <time.h>

    int main()
    {
        struct timespec start_hk, end_hk, start_hmc, end_hmc, start_gy, end_gy, start_lm, end_lm;
        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &start_hk);
        char *finalstr = (char* ) malloc(50);
        FILE *f = fopen("fullhk.txt", "a");
        if(f==NULL)
        {
            perror("Couldn't open file\n");
            exit(0);
        }
        //initialization of the three sensors
    //init_gy80();
        time_t curt;
        time(&curt);
        //fseek(f, 0, SEEK_END);
        sprintf(finalstr, "Time: %s\n", ctime(&curt));fputs(finalstr, f);   

        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &start_hmc);
        init_magnetometer();    
        sprintf(finalstr, "Bx: %f\n", get_Bx());fputs(finalstr, f);
        sprintf(finalstr, "By: %f\n", get_By());fputs(finalstr, f);
        sprintf(finalstr, "Bz: %f\n", get_Bz());fputs(finalstr, f);
        clear_magnetometer();
        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &end_hmc);

        sprintf(finalstr, "S1: %f\n", get_S1());fputs(finalstr, f);
        sprintf(finalstr, "S2: %f\n", get_S2());fputs(finalstr, f);
        sprintf(finalstr, "S3: %f\n", get_S3());fputs(finalstr, f);
        sprintf(finalstr, "S4: %f\n", get_S4());fputs(finalstr, f);
        sprintf(finalstr, "S5: %f\n", get_S5());fputs(finalstr, f);

        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &start_lm);
        init_LM75();           
        sprintf(finalstr, "Temperature: %d\n", get_temp());fputs(finalstr, f);
        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &end_lm);

        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &start_gy);
        init_gy521();      
        sprintf(finalstr, "Wy: %f\n", get_Wy());fputs(finalstr, f);
        sprintf(finalstr, "Wz: %f\n", get_Wz());fputs(finalstr, f);
        sprintf(finalstr, "Ax: %f\n", get_Ax());fputs(finalstr, f);
        sprintf(finalstr, "Ay: %f\n", get_Ay());fputs(finalstr, f);
        sprintf(finalstr, "Az: %f *end of block*\n\n", get_Az());
        clear_gy521();
        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &end_gy);

        fputs(finalstr, f);
        fclose(f);

        //closing the three sensors
        //clear_gy80();

        free(finalstr);
        clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &end_hk);
        printf("Time taken by single hmc instance: %ld microseconds\n", (end_hmc.tv_sec-start_hmc.tv_sec)*1000000L + (end_hmc.tv_nsec-start_hmc.tv_nsec)/1000);
        printf("Time taken by single gy instance: %ld microseconds\n", (end_gy.tv_sec-start_gy.tv_sec)*1000000L + (end_gy.tv_nsec-start_gy.tv_nsec)/1000);
        printf("Time taken by single lm instance: %ld microseconds\n", (end_lm.tv_sec-start_lm.tv_sec)*1000000L + (end_lm.tv_nsec-start_lm.tv_nsec)/1000);
        printf("Time taken by single housekeeping instance: %ld microseconds\n", (end_hk.tv_sec-start_hk.tv_sec)*1000000L + (end_hk.tv_nsec-start_hk.tv_nsec)/1000);
    }

Housekeeping is the name of the single module and the outputs above the housekeeping output are for the individual sensor modules. The housekeeping module has been compiled and linked with the sensor modules without the main function, and the O2 optimization flag has been used during cross compilation. This difference in the times is same even if the time is measured by CLOCK_BOOTTIME to include kernel pre-emption.

Please comment if any more information is needed to debunk this mystery!

Answer 1

I would suspect something happening in the background, when you use library functions for the first time.

Try to disable lazy binding, for example, by setting environment variable LD_BIND_NOW = 1 (Is there a linker flag to force it to load all shared libraries at start time?)