Stopwatch total time issue

Question

I have a project where I have to show time of the query to the server. Multiple Stopwatches are being used:

1) For webservice response(TechDoctimer)

2) For db response (dbTimer)

3) For total time of function performance (timer) this timer is "the biggest one", all the other timers are nested inside its performance.

So as a result I have to get 2 numbers (from db and techdoc stopwatch), sum of which would be less then timer, but I get something like this:

Server total response time: 1.351 (seconds)

TechDoc total response time: 1.215 (seconds)

Database prices total response time: 0.67 (seconds)

As you can see TechDoc+Database > Server total response time. I cant understand how could this happen, if only Visual Studio doesn`t do threading on its own.

Here is the code of my function:

 public static FullModel GetDetailList(string article)
    {
        Stopwatch timer = new Stopwatch();
        timer.Start();
        Stopwatch dbTimer = new Stopwatch();
        Stopwatch TechDoctimer = new Stopwatch();

        var db = new TecAllianceEntities();
        FullModel model = new FullModel();
        model.details = new List<DetailModel>();
        List<string> listOfNo = new List<string>();
        int articleId;

        TechDoctimer.Start();
        List<int> listOfIdsFound = RequestDetailIdByArticle(article);
        TechDoctimer.Stop();


        foreach (var item in listOfIdsFound)
        {
            DetailModel detail = new DetailModel();
            detail.oeNumberList = new List<OENumberModel>();
            detail.documents = new List<DocumentModel>();
            detail.attributeList = new List<AttributeModel>();

            articleId = item;

            TechDoctimer.Start();
            string resultFromRequestDetailById = TecAllianceResponce.RequestDetailByIds(articleId);
            TechDoctimer.Stop();

            var result = TecAllianceResponce.GetSorted(resultFromRequestDetailById);

            for (int i = 0; i < result.Count; i++)
            {
                switch (result[i])
                {
                    case "articleId":
                        detail.articleId = Int32.Parse(result[i + 1]);
                        break;

                    case "articleName":
                        detail.articleName = result[i + 1];
                        break;

                    case "articleNo":
                        detail.articleNo = result[i + 1];
                        listOfNo.Add(result[i + 1]);
                        break;

                    case "articleStateName":
                        detail.articleStateName = result[i + 1];
                        break;

                    case "brandName":
                        if (result[i - 2] == "articleStateName")
                            detail.brandName = result[i + 1];
                        break;

                    case "packingUnit":
                        detail.packingUnit = Int32.Parse(result[i + 1]);
                        break;

                    case "quantityPerPackingUnit":
                        detail.quantityPerPackingUnit = Int32.Parse(result[i + 1]);
                        break;

                    case "docId":
                        detail.hasDocuments = result[i + 1] != "0" ? true : false;
                        DocumentModel newDoc = new DocumentModel()
                        {
                            docId = Int32.Parse(result[i + 1]),
                            docFileName = result[i - 1],
                            docTypeName = result[i + 5]
                        };
                        newDoc.docURL = "http://webservicepilot.tecdoc.net/pegasus-3-0/documents/367/" + newDoc.docId + "/" + 0;
                        detail.documents.Add(newDoc);
                        break;

                    case "oeNumber":
                        detail.hasDocuments = result[i + 1] != "0" ? true : false;
                        OENumberModel newOE = new OENumberModel()
                        {
                            brandName = result[i - 1],
                            oeNumber = result[i + 1]
                        };
                        detail.oeNumberList.Add(newOE);
                        break;

                    case "attrName":
                        AttributeModel newAttr = new AttributeModel()
                        {
                            attrName = result[i + 1]
                        };
                        for (int j = i; j <= i + 12; j++)
                        {
                            if (result[j] == "attrValue") newAttr.attrValue = result[j + 1];
                            if (result[j] == "attrUnit") newAttr.attrUnit = result[j + 1];
                        }
                        if (newAttr.attrUnit == null) newAttr.attrUnit = "";
                        detail.attributeList.Add(newAttr);
                        break;
                }
            }
            model.details.Add(detail);
        }

        dbTimer.Start();
        if (listOfNo.Any())
        {
            var queryPrices = db.PRECES.Where(p => listOfNo.Contains(p.RAZOTAJA_KODI)).Select(p => new { p.RAZOTAJA_KODI, p.REALIZ_CENA }).ToList();
            dbTimer.Stop();
            foreach (var item in model.details)
            {
                try
                {
                    item.price = queryPrices.Where(q => q.RAZOTAJA_KODI == item.articleNo).Select(q => q.REALIZ_CENA).First();
                }
                catch
                {
                    item.price = 0;
                }
            }
        }
        else
        {
            dbTimer.Stop();
        }

        timer.Stop();
        TimeSpan timeTaken = timer.Elapsed;
        TimeSpan TechDocUsageTime = TechDoctimer.Elapsed;
        TimeSpan dbRequestTime = dbTimer.Elapsed;

        model.dbTimeTaken = dbRequestTime.Seconds + "." + dbRequestTime.Milliseconds;
        model.TimeTaken = timeTaken.Seconds + "." + timeTaken.Milliseconds;
        model.TimeTechDoc = TechDocUsageTime.Seconds + "." + TechDocUsageTime.Milliseconds;

        return model;
    }
}

Answer 1

Seeing as you are saving the result to a string, why don't you just use the TimeSpan.ToString() output?